On Mon, Jul 11, 2016 at 8:04 AM, Goncalo Borges <goncalo.borges@xxxxxxxxxxxxx> wrote: > Hi John... > > Thank you for replying. > > Here is the result of the tests you asked but I do not see nothing abnormal. Thanks for running through that. Yes, nothing in the output struck me as unreasonable either :-/ > Actually, your suggestions made me see that: > > 1) ceph-fuse 9.2.0 is presenting the same behaviour but with less memory > consumption, probably, less enought so that it doesn't brake ceph-fuse in > our machines with less memory. > > 2) I see a tremendous number of ceph-fuse threads launched (around 160). Unless you're using the async messenger, Ceph creates threads for each OSD connection, so it's normal to have a significant number of threads (e.g. if you had about 80 OSDs that would explain your thread count). John > # ps -T -p 3230 -o command,ppid,pid,spid,vsize,rss,%mem,%cpu | wc -l > 157 > > # ps -T -p 3230 -o command,ppid,pid,spid,vsize,rss,%mem,%cpu | head -n 10 > COMMAND PPID PID SPID VSZ RSS %MEM %CPU > ceph-fuse --id mount_user - 1 3230 3230 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3231 9935240 339780 0.6 0.1 > ceph-fuse --id mount_user - 1 3230 3232 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3233 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3234 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3235 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3236 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3237 9935240 339780 0.6 0.0 > ceph-fuse --id mount_user - 1 3230 3238 9935240 339780 0.6 0.0 > > > I do not see a way to actually limit the number of ceph-fuse threads > launched or to limit the max vm size each thread should take. > > Do you know how to limit those options. > > Cheers > > Goncalo > > > > > 1.> Try running ceph-fuse with valgrind --tool=memcheck to see if it's > leaking > > I have launched ceph-fuse with valgrind in the cluster where there is > sufficient memory available, and therefore, there is no object cacher > segfault. > > $ valgrind --log-file=/tmp/valgrind-ceph-fuse-10.2.2.txt --tool=memcheck > ceph-fuse --id mount_user -k /etc/ceph/ceph.client.mount_user.keyring -m > X.X.X.8:6789 -r /cephfs /coepp/cephfs > > This is the output which I get once I unmount the file system after user > application execution > > # cat valgrind-ceph-fuse-10.2.2.txt > ==12123== Memcheck, a memory error detector > ==12123== Copyright (C) 2002-2012, and GNU GPL'd, by Julian Seward et al. > ==12123== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info > ==12123== Command: ceph-fuse --id mount_user -k > /etc/ceph/ceph.client.mount_user.keyring -m 192.231.127.8:6789 -r /cephfs > /coepp/cephfs > ==12123== Parent PID: 11992 > ==12123== > ==12123== > ==12123== HEAP SUMMARY: > ==12123== in use at exit: 29,129 bytes in 397 blocks > ==12123== total heap usage: 14,824 allocs, 14,427 frees, 648,030 bytes > allocated > ==12123== > ==12123== LEAK SUMMARY: > ==12123== definitely lost: 16 bytes in 1 blocks > ==12123== indirectly lost: 0 bytes in 0 blocks > ==12123== possibly lost: 11,705 bytes in 273 blocks > ==12123== still reachable: 17,408 bytes in 123 blocks > ==12123== suppressed: 0 bytes in 0 blocks > ==12123== Rerun with --leak-check=full to see details of leaked memory > ==12123== > ==12123== For counts of detected and suppressed errors, rerun with: -v > ==12123== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 8 from 6) > ==12126== > ==12126== HEAP SUMMARY: > ==12126== in use at exit: 9,641 bytes in 73 blocks > ==12126== total heap usage: 31,363,579 allocs, 31,363,506 frees, > 41,389,143,617 bytes allocated > ==12126== > ==12126== LEAK SUMMARY: > ==12126== definitely lost: 28 bytes in 1 blocks > ==12126== indirectly lost: 0 bytes in 0 blocks > ==12126== possibly lost: 0 bytes in 0 blocks > ==12126== still reachable: 9,613 bytes in 72 blocks > ==12126== suppressed: 0 bytes in 0 blocks > ==12126== Rerun with --leak-check=full to see details of leaked memory > ==12126== > ==12126== For counts of detected and suppressed errors, rerun with: -v > ==12126== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 17 from 9) > > --- * --- > > 2.> Inspect inode count (ceph daemon <path to asok> status) to see if it's > obeying its limit > > This is the output I get once ceph-fuse is mounted but no user application > is running > > # ceph daemon /var/run/ceph/ceph-client.mount_user.asok status > { > "metadata": { > "ceph_sha1": "45107e21c568dd033c2f0a3107dec8f0b0e58374", > "ceph_version": "ceph version 10.2.2 > (45107e21c568dd033c2f0a3107dec8f0b0e58374)", > "entity_id": "mount_user", > "hostname": "<some host name>", > "mount_point": "\/coepp\/cephfs", > "root": "\/cephfs" > }, > "dentry_count": 0, > "dentry_pinned_count": 0, > "inode_count": 2, > "mds_epoch": 817, > "osd_epoch": 1005, > "osd_epoch_barrier": 0 > } > > > This is already when ceph-fuse reached 10g of virtual memory, and user > applications are hammering the filesystem. > > # ceph daemon /var/run/ceph/ceph-client.mount_user.asok status > { > "metadata": { > "ceph_sha1": "45107e21c568dd033c2f0a3107dec8f0b0e58374", > "ceph_version": "ceph version 10.2.2 > (45107e21c568dd033c2f0a3107dec8f0b0e58374)", > "entity_id": "mount_user", > "hostname": "<some host name>", > "mount_point": "\/coepp\/cephfs", > "root": "\/cephfs" > }, > "dentry_count": 13, > "dentry_pinned_count": 2, > "inode_count": 15, > "mds_epoch": 817, > "osd_epoch": 1005, > "osd_epoch_barrier": 1005 > } > > Once I kill the applications I get > > # ceph daemon /var/run/ceph/ceph-client.mount_user.asok status > { > "metadata": { > "ceph_sha1": "45107e21c568dd033c2f0a3107dec8f0b0e58374", > "ceph_version": "ceph version 10.2.2 > (45107e21c568dd033c2f0a3107dec8f0b0e58374)", > "entity_id": "mount_user", > "hostname": "<some host name>", > "mount_point": "\/coepp\/cephfs", > "root": "\/cephfs" > }, > "dentry_count": 38, > "dentry_pinned_count": 3, > "inode_count": 40, > "mds_epoch": 817, > "osd_epoch": 1005, > "osd_epoch_barrier": 1005 > } > > --- * --- > > 3.> Enable objectcacher debug (debug objectcacher = 10) and look at the > output (from the "trim" lines) to see if it's obeying its limit > > I've mounted ceph-fuse with debug objectcacher = 10, and filled the host > with user applications. I killed the applications when I saw ceph-fuse > virtual > memory stabilize at around 10g. > > Greping for the trim lines in the log, this is the structure I've found: > > 2016-07-11 01:55:46.314888 7f04c57fb700 10 objectcacher trim start: > bytes: max 209715200 clean 0, objects: max 1000 current 1 > 2016-07-11 01:55:46.314891 7f04c57fb700 10 objectcacher trim finish: > max 209715200 clean 0, objects: max 1000 current 1 > 2016-07-11 01:55:46.315009 7f04c75fe700 10 objectcacher trim start: > bytes: max 209715200 clean 0, objects: max 1000 current 2 > 2016-07-11 01:55:46.315012 7f04c75fe700 10 objectcacher trim finish: > max 209715200 clean 0, objects: max 1000 current 2 > <... snip ... > > 2016-07-11 01:56:09.444853 7f04c75fe700 10 objectcacher trim start: > bytes: max 209715200 clean 204608008, objects: max 1000 current 55 > 2016-07-11 01:56:09.444855 7f04c75fe700 10 objectcacher trim finish: > max 209715200 clean 204608008, objects: max 1000 current 55 > 2016-07-11 01:56:09.445010 7f04c57fb700 10 objectcacher trim start: > bytes: max 209715200 clean 204608008, objects: max 1000 current 55 > 2016-07-11 01:56:09.445011 7f04c57fb700 10 objectcacher trim finish: > max 209715200 clean 204608008, objects: max 1000 current 55 > 2016-07-11 01:56:09.798269 7f04c75fe700 10 objectcacher trim start: > bytes: max 209715200 clean 210943832, objects: max 1000 current 55 > 2016-07-11 01:56:09.798272 7f04c75fe700 10 objectcacher trim trimming > bh[ 0x7f04a8016100 96~59048 0x7f04a8014cd0 (59048) v 3 clean firstbyte=1] > waiters = {} > 2016-07-11 01:56:09.798284 7f04c75fe700 10 objectcacher trim trimming > bh[ 0x7f04b4011550 96~59048 0x7f04b4010430 (59048) v 4 clean firstbyte=1] > waiters = {} > 2016-07-11 01:56:09.798294 7f04c75fe700 10 objectcacher trim trimming > bh[ 0x7f04b001bea0 61760~4132544 0x7f04b4010430 (4132544) v 24 clean > firstbyte=71] waiters = {} > 2016-07-11 01:56:09.798395 7f04c75fe700 10 objectcacher trim finish: > max 209715200 clean 206693192, objects: max 1000 current 55 > 2016-07-11 01:56:09.798687 7f04c57fb700 10 objectcacher trim start: > bytes: max 209715200 clean 206693192, objects: max 1000 current 55 > 2016-07-11 01:56:09.798689 7f04c57fb700 10 objectcacher trim finish: > max 209715200 clean 206693192, objects: max 1000 current 55 > <... snip ...> > 2016-07-11 01:56:10.494928 7f04c75fe700 10 objectcacher trim start: > bytes: max 209715200 clean 210806408, objects: max 1000 current 55 > 2016-07-11 01:56:10.494931 7f04c75fe700 10 objectcacher trim trimming > bh[ 0x7f04b401a760 61760~4132544 0x7f04a8014cd0 (4132544) v 32 clean > firstbyte=71] waiters = {} > 2016-07-11 01:56:10.495058 7f04c75fe700 10 objectcacher trim finish: > max 209715200 clean 206673864, objects: max 1000 current 55 > <... snip ...> > 2016-07-11 01:57:08.333503 7f04c6bfd700 10 objectcacher trim start: > bytes: max 209715200 clean 211528796, objects: max 1000 current 187 > 2016-07-11 01:57:08.333507 7f04c6bfd700 10 objectcacher trim trimming > bh[ 0x7f04b0b370e0 0~4194304 0x7f04b09f2630 (4194304) v 404 clean > firstbyte=84] waiters = {} > 2016-07-11 01:57:08.333708 7f04c6bfd700 10 objectcacher trim finish: > max 209715200 clean 207334492, objects: max 1000 current 187 > 2016-07-11 01:57:08.616143 7f04c61fc700 10 objectcacher trim start: > bytes: max 209715200 clean 209949683, objects: max 1000 current 188 > 2016-07-11 01:57:08.616146 7f04c61fc700 10 objectcacher trim trimming > bh[ 0x7f04a8bfdd60 0~4194304 0x7f04a8bfe660 (4194304) v 407 clean > firstbyte=84] waiters = {} > 2016-07-11 01:57:08.616303 7f04c61fc700 10 objectcacher trim finish: > max 209715200 clean 205755379, objects: max 1000 current 188 > 2016-07-11 01:57:08.936060 7f04c57fb700 10 objectcacher trim start: > bytes: max 209715200 clean 205760010, objects: max 1000 current 189 > 2016-07-11 01:57:08.936063 7f04c57fb700 10 objectcacher trim finish: > max 209715200 clean 205760010, objects: max 1000 current 189 > 2016-07-11 01:58:02.918322 7f04f27f4e40 10 objectcacher release trimming > object[100003dffd9.00000000/head oset 0x7f04d4045c98 wr 566/566] > 2016-07-11 01:58:02.918335 7f04f27f4e40 10 objectcacher release trimming > object[100003dffd5.00000000/head oset 0x7f04d403e378 wr 564/564] > <... snip...> > 2016-07-11 01:58:02.924699 7f04f27f4e40 10 objectcacher release trimming > object[100003dffc4.0000000f/head oset 0x7f04d402b308 wr 557/557] > 2016-07-11 01:58:02.924717 7f04f27f4e40 10 objectcacher release trimming > object[100003dffc5.00000000/head oset 0x7f04d40026b8 wr 541/541] > 2016-07-11 01:58:02.924769 7f04f27f4e40 10 objectcacher release trimming > object[100003dffc8.00000000/head oset 0x7f04d4027818 wr 547/547] > <... snip...> > 2016-07-11 01:58:02.925879 7f04f27f4e40 10 objectcacher release_set on > 0x7f04d401a568 dne > 2016-07-11 01:58:02.925881 7f04f27f4e40 10 objectcacher release_set on > 0x7f04d401b078 dne > 2016-07-11 01:58:02.957626 7f04e57fb700 10 objectcacher flusher finish > > So, if I am understanding this correctly, every time the client_oc_size > bytes of cached data is above 200M bytes, it is trimmed and the values is > well kepted near its limit. > > > --- * --- > > 4.> See if fuse_disable_pagecache setting makes a difference > > It doesn't seem to make a difference. I've set in ceph config > > # grep fuse /etc/ceph/ceph.conf > fuse_disable_pagecache = true > > on this client (I guess I do not have to do it in the overall cluster). > Then, I've remounted cephfs via ceph-fuse and filled the host with user > applications. > > Almost immediatly this is what I got: > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 28681 root 20 0 8543m 248m 5948 S 4.0 0.5 0:02.73 ceph-fuse > 5369 root 20 0 3131m 231m 12m S 0.0 0.5 26:22.90 > dsm_om_connsvcd > 1429 goncalo 20 0 1595m 98m 32m R 99.5 0.2 1:04.34 python > 1098 goncalo 20 0 1596m 86m 20m R 99.9 0.2 1:04.29 python > 994 goncalo 20 0 1594m 86m 20m R 99.9 0.2 1:04.16 python > 31928 goncalo 20 0 1595m 86m 19m R 99.9 0.2 1:04.76 python > 16852 goncalo 20 0 1596m 86m 19m R 99.9 0.2 1:06.16 python > 16846 goncalo 20 0 1594m 84m 19m R 99.9 0.2 1:06.05 python > 29595 goncalo 20 0 1594m 83m 19m R 100.2 0.2 1:05.57 python > 29312 goncalo 20 0 1594m 83m 19m R 99.9 0.2 1:05.01 python > 31979 goncalo 20 0 1595m 82m 19m R 100.2 0.2 1:04.82 python > 29333 goncalo 20 0 1594m 82m 19m R 99.5 0.2 1:04.94 python > 29609 goncalo 20 0 1594m 82m 19m R 99.9 0.2 1:05.07 python > > > 5.> Also, is the version of fuse the same on the nodes running 9.2.0 vs. the > nodes running 10.2.2? > > In 10.2.2 I've compiled with fuse 2.9.7 while in 9.2.0 I've compiled against > the default sl6 fuse libs version 2.8.7. However, as I said before, I am > seeing the same issue with 9.2.0 (although with a bit less of used virtual > memory in total). > > > > > On 07/08/2016 10:53 PM, John Spray wrote: > > On Fri, Jul 8, 2016 at 8:01 AM, Goncalo Borges > <goncalo.borges@xxxxxxxxxxxxx> wrote: > > Hi Brad, Patrick, All... > > I think I've understood this second problem. In summary, it is memory > related. > > This is how I found the source of the problem: > > 1./ I copied and adapted the user application to run in another cluster of > ours. The idea was for me to understand the application and run it myself to > collect logs and so on... > > 2./ Once I submit it to this other cluster, every thing went fine. I was > hammering cephfs from multiple nodes without problems. This pointed to > something different between the two clusters. > > 3./ I've started to look better to the segmentation fault message, and > assuming that the names of the methods and functions do mean something, the > log seems related to issues on the management of objects in cache. This > pointed to a memory related problem. > > 4./ On the cluster where the application run successfully, machines have > 48GB of RAM and 96GB of SWAP (don't know why we have such a large SWAP size, > it is a legacy setup). > > # top > top - 00:34:01 up 23 days, 22:21, 1 user, load average: 12.06, 12.12, > 10.40 > Tasks: 683 total, 13 running, 670 sleeping, 0 stopped, 0 zombie > Cpu(s): 49.7%us, 0.6%sy, 0.0%ni, 49.7%id, 0.1%wa, 0.0%hi, 0.0%si, > 0.0%st > Mem: 49409308k total, 29692548k used, 19716760k free, 433064k buffers > Swap: 98301948k total, 0k used, 98301948k free, 26742484k cached > > 5./ I have noticed that ceph-fuse (in 10.2.2) consumes about 1.5 GB of > virtual memory when there is no applications using the filesystem. > > 7152 root 20 0 1108m 12m 5496 S 0.0 0.0 0:00.04 ceph-fuse > > When I only have one instance of the user application running, ceph-fuse (in > 10.2.2) slowly rises with time up to 10 GB of memory usage. > > if I submit a large number of user applications simultaneously, ceph-fuse > goes very fast to ~10GB. > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 18563 root 20 0 10.0g 328m 5724 S 4.0 0.7 1:38.00 ceph-fuse > 4343 root 20 0 3131m 237m 12m S 0.0 0.5 28:24.56 dsm_om_connsvcd > 5536 goncalo 20 0 1599m 99m 32m R 99.9 0.2 31:35.46 python > 31427 goncalo 20 0 1597m 89m 20m R 99.9 0.2 31:35.88 python > 20504 goncalo 20 0 1599m 89m 20m R 100.2 0.2 31:34.29 python > 20508 goncalo 20 0 1599m 89m 20m R 99.9 0.2 31:34.20 python > 4973 goncalo 20 0 1599m 89m 20m R 99.9 0.2 31:35.70 python > 1331 goncalo 20 0 1597m 88m 20m R 99.9 0.2 31:35.72 python > 20505 goncalo 20 0 1597m 88m 20m R 99.9 0.2 31:34.46 python > 20507 goncalo 20 0 1599m 87m 20m R 99.9 0.2 31:34.37 python > 28375 goncalo 20 0 1597m 86m 20m R 99.9 0.2 31:35.52 python > 20503 goncalo 20 0 1597m 85m 20m R 100.2 0.2 31:34.09 python > 20506 goncalo 20 0 1597m 84m 20m R 99.5 0.2 31:34.42 python > 20502 goncalo 20 0 1597m 83m 20m R 99.9 0.2 31:34.32 python > > 6./ On the machines where the user had the segfault, we have 16 GB of RAM > and 1GB of SWAP > > Mem: 16334244k total, 3590100k used, 12744144k free, 221364k buffers > Swap: 1572860k total, 10512k used, 1562348k free, 2937276k cached > > 7./ I think what is happening is that once the user submits his sets of > jobs, the memory usage goes to the very limit on this type machine, and the > raise is actually to fast that ceph-fuse segfaults before OOM Killer can > kill it. > > 8./ We have run the user application in the same type of machines but with > 64 GB of RAM and 1GB of SWAP, and everything goes fine also here. > > > So, in conclusion, our second problem (besides the locks which was fixed by > Pat patch) is the memory usage profile of ceph-fuse in 10.2.2 which seems to > be very different than what it was in ceph-fuse 9.2.0. > > Are there any ideas how can we limit the virtual memory usage of ceph-fuse > in 10.2.2? > > The fuse client is designed to limit its cache sizes: > client_cache_size (default 16384) inodes of cached metadata > client_oc_size (default 200MB) bytes of cached data > > We do run the fuse client with valgrind during testing, so it it is > showing memory leaks in normal usage on your system then that's news. > > The top output you've posted seems to show that ceph-fuse only > actually has 328MB resident though? > > If you can reproduce the memory growth, then it would be good to: > * Try running ceph-fuse with valgrind --tool=memcheck to see if it's > leaking > * Inspect inode count (ceph daemon <path to asok> status) to see if > it's obeying its limit > * Enable objectcacher debug (debug objectcacher = 10) and look at the > output (from the "trim" lines) to see if it's obeying its limit > * See if fuse_disable_pagecache setting makes a difference > > Also, is the version of fuse the same on the nodes running 9.2.0 vs. > the nodes running 10.2.2? > > John > > Cheers > Goncalo > > > > On 07/08/2016 09:54 AM, Brad Hubbard wrote: > > Hi Goncalo, > > If possible it would be great if you could capture a core file for this with > full debugging symbols (preferably glibc debuginfo as well). How you do > that will depend on the ceph version and your OS but we can offfer help > if required I'm sure. > > Once you have the core do the following. > > $ gdb /path/to/ceph-fuse core.XXXX > (gdb) set pag off > (gdb) set log on > (gdb) thread apply all bt > (gdb) thread apply all bt full > > Then quit gdb and you should find a file called gdb.txt in your > working directory. > If you could attach that file to http://tracker.ceph.com/issues/16610 > > Cheers, > Brad > > On Fri, Jul 8, 2016 at 12:06 AM, Patrick Donnelly <pdonnell@xxxxxxxxxx> > wrote: > > On Thu, Jul 7, 2016 at 2:01 AM, Goncalo Borges > <goncalo.borges@xxxxxxxxxxxxx> wrote: > > Unfortunately, the other user application breaks ceph-fuse again (It is a > completely different application then in my previous test). > > We have tested it in 4 machines with 4 cores. The user is submitting 16 > single core jobs which are all writing different output files (one per job) > to a common dir in cephfs. The first 4 jobs run happily and never break > ceph-fuse. But the remaining 12 jobs, running in the remaining 3 machines, > trigger a segmentation fault, which is completely different from the other > case. > > ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374) > 1: (()+0x297fe2) [0x7f54402b7fe2] > 2: (()+0xf7e0) [0x7f543ecf77e0] > 3: (ObjectCacher::bh_write_scattered(std::list<ObjectCacher::BufferHead*, > std::allocator<ObjectCacher::BufferHead*> >&)+0x36) [0x7f5440268086] > 4: (ObjectCacher::bh_write_adjacencies(ObjectCacher::BufferHead*, > std::chrono::time_point<ceph::time_detail::real_clock, > std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> > >, long*, > int*)+0x22c) [0x7f5440268a3c] > 5: (ObjectCacher::flush(long)+0x1ef) [0x7f5440268cef] > 6: (ObjectCacher::flusher_entry()+0xac4) [0x7f5440269a34] > 7: (ObjectCacher::FlusherThread::entry()+0xd) [0x7f5440275c6d] > 8: (()+0x7aa1) [0x7f543ecefaa1] > 9: (clone()+0x6d) [0x7f543df6893d] > NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to > interpret this. > > This one looks like a very different problem. I've created an issue > here: http://tracker.ceph.com/issues/16610 > > Thanks for the report and debug log! > > -- > Patrick Donnelly > _______________________________________________ > ceph-users mailing list > ceph-users@xxxxxxxxxxxxxx > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com > > > > -- > Goncalo Borges > Research Computing > ARC Centre of Excellence for Particle Physics at the Terascale > School of Physics A28 | University of Sydney, NSW 2006 > T: +61 2 93511937 > > > _______________________________________________ > ceph-users mailing list > ceph-users@xxxxxxxxxxxxxx > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com > > > -- > Goncalo Borges > Research Computing > ARC Centre of Excellence for Particle Physics at the Terascale > School of Physics A28 | University of Sydney, NSW 2006 > T: +61 2 93511937 _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com