Ceph » CephFS

FYI: These hangs may have just been caused by osd failures (see #1473). I will update if this issue persists.

Only 3 osds crashed though. It seems like there should be other PGs on other osds that are still accessible, unless its the root directory entry that was lost. Any reason a client hang for access to a specific object seems to hang all requests?

Well with 3 OSDs down you probably lost access to some objects?

It probably shouldn't hang all other requests on that client, though, and I don't think we expect it to. Hrm.

I have verified that this hang is not due to osds crashing. With all osds running, and all pgs active+clean, I still see a hang that appears for a random request (in this case open). Please change the state back to NEW.

#0 0x00007f1b534f6bac in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00000000006a4cf1 in Cond::Wait (this=0x7ffff8d9edb0, mutex=...) at ../../src/common/Cond.h:46
#2 0x000000000066f614 in Client::make_request (this=0x1b96380, request=0x1bc62c0, uid=1005, gid=1006,
ptarget=0x0, use_mds=-1, pdirbl=0x0) at ../../src/client/Client.cc:1090
#3 0x000000000068f5b2 in Client::_open (this=0x1b96380, in=0x2373000, flags=557569, mode=0,
fhp=0x7ffff8d9efc8, uid=1005, gid=1006) at ../../src/client/Client.cc:4894
#4 0x000000000069f3cb in Client::ll_open (this=0x1b96380, vino=..., flags=557569, fhp=0x7ffff8d9efc8,
uid=1005, gid=1006) at ../../src/client/Client.cc:6684
#5 0x000000000066088a in ceph_ll_open (req=0x31a3300, ino=1099511674773, fi=0x7ffff8d9f010)
at ../../src/client/fuse_ll.cc:321
#6 0x00007f1b5371c609 in ?? () from /lib/libfuse.so.2
#7 0x00007f1b53719cb5 in fuse_session_loop () from /lib/libfuse.so.2
#8 0x0000000000661749 in ceph_fuse_ll_main (c=0x1b96380, argc=4, argv=0x1ba0000, fd=5)
at ../../src/client/fuse_ll.cc:610
#9 0x0000000000658154 in main (argc=4, argv=0x1ba0000, envp=0x1b90000) at ../../src/cfuse.cc:134

At most 20 processes running at any given time (different instances of the same application) from a single client, reading from a single file and writing to a number of files (10-100). The I/O is fairly small, 4K - 100K max. I've had two nodes running 20 processes each, but the hang seems to occur when just one node is running a bunch of processes. If this doesn't help I can try to see if I can boil it down to a bunch of dd invocations.

At about the time of that last client hang (_open), I do see these messages in the active mds log:

2011-08-31 17:03:59.733358 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.12:6805/23032
2011-08-31 17:03:59.734104 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.12:6805/23032
2011-08-31 17:03:59.755068 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.12:6801/22945
2011-08-31 17:03:59.755180 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.113:6808/21132
2011-08-31 17:03:59.755643 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.113:6808/21132
2011-08-31 17:03:59.755894 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.12:6801/22945
2011-08-31 17:04:06.587032 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.11:6801/9922
2011-08-31 17:04:06.587967 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.11:6801/9922
2011-08-31 17:04:36.432770 7fabc86f7700 log [INF] : closing stale session client4485 192.168.101.12:6817/26283 after 303.504888
2011-08-31 17:06:21.703432 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.112:6812/28315
2011-08-31 17:06:21.704500 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.112:6812/28315
2011-08-31 17:06:22.545024 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.11:6805/9988
2011-08-31 17:06:22.545885 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.11:6805/9988
2011-08-31 17:06:22.797398 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.115:6804/12467
2011-08-31 17:06:22.798340 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.115:6804/12467
2011-08-31 17:06:23.055043 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.12:6809/23976
2011-08-31 17:06:23.055960 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.12:6809/23976
2011-08-31 17:06:31.575124 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.111:6804/10832
2011-08-31 17:06:31.575950 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.111:6804/10832
2011-08-31 17:09:21.273347 7fabc58d7700 -- 192.168.101.13:6800/20377 >> 192.168.101.12:6817/26283 pipe(0x28d8280 sd=44 pgs=0 cs=0 l=0).accept we reset (peer sent cseq 2), sending RESETSESSION
2011-08-31 17:09:35.174258 7fabc58d7700 -- 192.168.101.13:6800/20377 >> 192.168.101.12:6817/26283 pipe(0x28d8280 sd=44 pgs=87 cs=1 l=0).fault with nothing to send, going to standby
2011-08-31 17:10:35.565032 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.114:6800/10529
2011-08-31 17:10:35.566027 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.114:6800/10529
2011-08-31 17:15:36.504990 7fabc97fa700 mds0.3 ms_handle_reset on 192.168.101.14:6801/10211
2011-08-31 17:15:36.505865 7fabc97fa700 mds0.3 ms_handle_connect on 192.168.101.14:6801/10211

Again stuck in an open:

(gdb) bt
#0 0x00007f7407a33bac in pthread_cond_wait@@GLIBC_2.3.2 ()
from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00000000006a4cf1 in Cond::Wait (this=0x7fff826b7740, mutex=...)
at ../../src/common/Cond.h:46
#2 0x000000000066f614 in Client::make_request (this=0x1e81380,
request=0x1eb12c0, uid=1005, gid=1006, ptarget=0x0, use_mds=-1, pdirbl=0x0)
at ../../src/client/Client.cc:1090
#3 0x000000000068f5b2 in Client::_open (this=0x1e81380, in=0x52b2480,
flags=557569, mode=0, fhp=0x7fff826b7958, uid=1005, gid=1006)
at ../../src/client/Client.cc:4894
#4 0x000000000069f3cb in Client::ll_open (this=0x1e81380, vino=...,
flags=557569, fhp=0x7fff826b7958, uid=1005, gid=1006)
at ../../src/client/Client.cc:6684

After the hang, I enabled the debugging on the active mds. Here's the beginning of the output. I can't publish the whole log, but if there's something specific to look for, let me know.

2011-09-01 09:50:16.207363 7fabc97fa700 mds0.3 applying configuration change: debug_mds = '10'

2011-09-01 09:50:16.798325 7fabc86f7700 mds0.3 beacon_send up:active seq 16721 (currently up:active)
2011-09-01 09:50:16.799618 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16721 rtt 0.001260
2011-09-01 09:50:17.310978 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3003) v1 from client4493
2011-09-01 09:50:18.878897 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:18.879933 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:18.908815 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383332, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:18.908838 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / 1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:18.908849 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:18.908907 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:18.908992 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:18.909074 7fabc86f7700 mds0.bal mds0 epoch 6682 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:50:18.910580 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:20.798492 7fabc86f7700 mds0.3 beacon_send up:active seq 16722 (currently up:active)
2011-09-01 09:50:20.799792 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16722 rtt 0.001268
2011-09-01 09:50:23.805971 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3284) v1 from client4469
2011-09-01 09:50:23.852268 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3284) v1 from client4477
2011-09-01 09:50:23.879100 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:23.879128 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:23.880158 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383336, heap 168356, malloc 215144 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:23.880174 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:23.880184 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:23.880238 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:23.880250 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:23.880262 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:24.798657 7fabc86f7700 mds0.3 beacon_send up:active seq 16723 (currently up:active)
2011-09-01 09:50:24.799935 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16723 rtt 0.001245
2011-09-01 09:50:26.681915 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3282) v1 from client4481
2011-09-01 09:50:28.798820 7fabc86f7700 mds0.3 beacon_send up:active seq 16724 (currently up:active)
2011-09-01 09:50:28.800114 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16724 rtt 0.001260
2011-09-01 09:50:28.879301 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:28.879329 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:28.880352 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:28.880367 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:28.880377 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:28.880428 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:28.880440 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:28.880528 7fabc86f7700 mds0.bal mds0 epoch 6683 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:50:28.880547 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:32.798968 7fabc86f7700 mds0.3 beacon_send up:active seq 16725 (currently up:active)
2011-09-01 09:50:32.800721 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16725 rtt 0.001721
2011-09-01 09:50:33.879505 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:33.879536 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:33.880602 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:33.880617 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:33.880626 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:33.880678 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:33.880690 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:33.880703 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:36.799090 7fabc86f7700 mds0.3 beacon_send up:active seq 16726 (currently up:active)
2011-09-01 09:50:36.800455 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16726 rtt 0.001333
2011-09-01 09:50:37.312293 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3004) v1 from client4493
2011-09-01 09:50:38.879706 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:38.879734 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:38.880749 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:38.880764 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:38.880773 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:38.880824 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:38.880836 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:38.880908 7fabc86f7700 mds0.bal mds0 epoch 6684 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:50:38.880926 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:40.799250 7fabc86f7700 mds0.3 beacon_send up:active seq 16727 (currently up:active)
2011-09-01 09:50:40.800584 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16727 rtt 0.001302
2011-09-01 09:50:43.808025 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3285) v1 from client4469
2011-09-01 09:50:43.854492 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3285) v1 from client4477
2011-09-01 09:50:43.879906 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:43.879934 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:43.880817 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215144 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:43.880831 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:43.880841 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:43.880893 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:43.880905 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:43.880916 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:44.799412 7fabc86f7700 mds0.3 beacon_send up:active seq 16728 (currently up:active)
2011-09-01 09:50:44.800735 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16728 rtt 0.001293
2011-09-01 09:50:46.684293 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3283) v1 from client4481
2011-09-01 09:50:48.799575 7fabc86f7700 mds0.3 beacon_send up:active seq 16729 (currently up:active)
2011-09-01 09:50:48.800956 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16729 rtt 0.001349
2011-09-01 09:50:48.880078 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:48.880109 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:48.881352 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:48.881367 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:48.881377 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:48.881429 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:48.881441 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:48.881515 7fabc86f7700 mds0.bal mds0 epoch 6685 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:50:48.881534 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:52.799714 7fabc86f7700 mds0.3 beacon_send up:active seq 16730 (currently up:active)
2011-09-01 09:50:52.801196 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16730 rtt 0.001446
2011-09-01 09:50:53.880281 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:53.880312 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:53.881215 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:53.881230 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:53.881240 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:53.881293 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:53.881305 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:53.881319 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:50:56.799885 7fabc86f7700 mds0.3 beacon_send up:active seq 16731 (currently up:active)
2011-09-01 09:50:56.801228 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16731 rtt 0.001305
2011-09-01 09:50:57.314517 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3005) v1 from client4493
2011-09-01 09:50:58.880483 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:50:58.880516 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:50:58.881415 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215135 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:50:58.881431 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:50:58.881441 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:50:58.881492 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:50:58.881505 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:50:58.881578 7fabc86f7700 mds0.bal mds0 epoch 6686 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:50:58.881597 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:00.800052 7fabc86f7700 mds0.3 beacon_send up:active seq 16732 (currently up:active)
2011-09-01 09:51:00.801205 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16732 rtt 0.001123
2011-09-01 09:51:03.810151 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3286) v1 from client4469
2011-09-01 09:51:03.856715 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3286) v1 from client4477
2011-09-01 09:51:03.880682 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:03.880710 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:03.881638 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215144 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:03.881653 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:03.881663 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:03.881716 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:03.881727 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:03.881739 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:04.800212 7fabc86f7700 mds0.3 beacon_send up:active seq 16733 (currently up:active)
2011-09-01 09:51:04.801403 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16733 rtt 0.001159
2011-09-01 09:51:06.686657 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3284) v1 from client4481
2011-09-01 09:51:08.800358 7fabc86f7700 mds0.3 beacon_send up:active seq 16734 (currently up:active)
2011-09-01 09:51:08.801540 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16734 rtt 0.001148
2011-09-01 09:51:08.880884 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:08.880911 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:08.881781 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:08.881796 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:08.881805 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:08.881856 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:08.881868 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:08.881940 7fabc86f7700 mds0.bal mds0 epoch 6687 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:51:08.881958 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:12.800528 7fabc86f7700 mds0.3 beacon_send up:active seq 16735 (currently up:active)
2011-09-01 09:51:12.802001 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16735 rtt 0.001435
2011-09-01 09:51:13.881085 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:13.881114 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:13.881978 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:13.881993 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:13.882001 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:13.882053 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:13.882065 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:13.882078 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:16.800698 7fabc86f7700 mds0.3 beacon_send up:active seq 16736 (currently up:active)
2011-09-01 09:51:16.801935 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16736 rtt 0.001202
2011-09-01 09:51:17.316552 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3006) v1 from client4493
2011-09-01 09:51:18.881335 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:18.881369 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:18.882232 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:18.882257 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:18.882266 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:18.882318 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:18.882330 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:18.882403 7fabc86f7700 mds0.bal mds0 epoch 6688 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:51:18.882422 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:20.800864 7fabc86f7700 mds0.3 beacon_send up:active seq 16737 (currently up:active)
2011-09-01 09:51:20.802029 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16737 rtt 0.001133
2011-09-01 09:51:23.812334 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3287) v1 from client4469
2011-09-01 09:51:23.859046 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3287) v1 from client4477
2011-09-01 09:51:23.881583 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:23.881612 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:23.882461 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215145 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:23.882476 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:23.882487 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:23.882541 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:23.882553 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:23.882565 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:24.800982 7fabc86f7700 mds0.3 beacon_send up:active seq 16738 (currently up:active)
2011-09-01 09:51:24.802390 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16738 rtt 0.001376
2011-09-01 09:51:26.689091 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3285) v1 from client4481
2011-09-01 09:51:28.801145 7fabc86f7700 mds0.3 beacon_send up:active seq 16739 (currently up:active)
2011-09-01 09:51:28.802412 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16739 rtt 0.001232
2011-09-01 09:51:28.881782 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:28.881808 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:28.882578 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:28.882592 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:28.882602 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:28.882654 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:28.882666 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:28.882739 7fabc86f7700 mds0.bal mds0 epoch 6689 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:51:28.882759 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:32.801316 7fabc86f7700 mds0.3 beacon_send up:active seq 16740 (currently up:active)
2011-09-01 09:51:32.802731 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16740 rtt 0.001379
2011-09-01 09:51:33.881984 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:33.882013 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:33.882784 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:33.882810 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:33.882819 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:33.882871 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:33.882883 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:33.882896 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:36.801486 7fabc86f7700 mds0.3 beacon_send up:active seq 16741 (currently up:active)
2011-09-01 09:51:36.802724 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16741 rtt 0.001203
2011-09-01 09:51:37.318790 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3007) v1 from client4493
2011-09-01 09:51:38.882216 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:38.882988 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:38.883002 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:38.883011 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:38.883062 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:38.883074 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:38.883145 7fabc86f7700 mds0.bal mds0 epoch 6690 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:51:38.883163 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:40.801654 7fabc86f7700 mds0.3 beacon_send up:active seq 16742 (currently up:active)
2011-09-01 09:51:40.803136 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16742 rtt 0.001449
2011-09-01 09:51:43.814424 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3288) v1 from client4469
2011-09-01 09:51:43.861108 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3288) v1 from client4477
2011-09-01 09:51:43.882387 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:43.882412 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:43.883311 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215145 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:43.883331 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:43.883345 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:43.883401 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:43.883413 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:43.883424 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:44.801812 7fabc86f7700 mds0.3 beacon_send up:active seq 16743 (currently up:active)
2011-09-01 09:51:44.803021 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16743 rtt 0.001178
2011-09-01 09:51:46.691474 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3286) v1 from client4481
2011-09-01 09:51:48.801971 7fabc86f7700 mds0.3 beacon_send up:active seq 16744 (currently up:active)
2011-09-01 09:51:48.803194 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16744 rtt 0.001190
2011-09-01 09:51:48.882588 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:48.882612 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:48.883405 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:48.883429 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:48.883439 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:48.883490 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:48.883502 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:48.883574 7fabc86f7700 mds0.bal mds0 epoch 6691 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:51:48.883593 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:52.802136 7fabc86f7700 mds0.3 beacon_send up:active seq 16745 (currently up:active)
2011-09-01 09:51:52.803367 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16745 rtt 0.001195
2011-09-01 09:51:53.882787 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:53.882814 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:53.883587 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:51:53.883600 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:53.883609 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:53.883660 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:53.883672 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:53.883685 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:51:56.802305 7fabc86f7700 mds0.3 beacon_send up:active seq 16746 (currently up:active)
2011-09-01 09:51:56.803520 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16746 rtt 0.001180
2011-09-01 09:51:57.320990 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3008) v1 from client4493
2011-09-01 09:51:58.882989 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:51:58.883017 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:51:58.883802 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:51:58.883811 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:51:58.883863 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:51:58.883875 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:51:58.883948 7fabc86f7700 mds0.bal mds0 epoch 6692 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:51:58.883967 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:00.802468 7fabc86f7700 mds0.3 beacon_send up:active seq 16747 (currently up:active)
2011-09-01 09:52:00.803731 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16747 rtt 0.001230
2011-09-01 09:52:03.816485 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3289) v1 from client4469
2011-09-01 09:52:03.863390 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3289) v1 from client4477
2011-09-01 09:52:03.883193 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:03.883218 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:03.883996 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215145 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:03.884011 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:03.884020 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:03.884073 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:03.884098 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:03.884111 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:04.802603 7fabc86f7700 mds0.3 beacon_send up:active seq 16748 (currently up:active)
2011-09-01 09:52:04.803804 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16748 rtt 0.001170
2011-09-01 09:52:06.693861 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3287) v1 from client4481
2011-09-01 09:52:08.802766 7fabc86f7700 mds0.3 beacon_send up:active seq 16749 (currently up:active)
2011-09-01 09:52:08.804512 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16749 rtt 0.001715
2011-09-01 09:52:08.883391 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:08.883416 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:08.884355 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:08.884373 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:08.884386 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:08.884440 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:08.884451 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:08.884523 7fabc86f7700 mds0.bal mds0 epoch 6693 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:52:08.884541 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:12.802930 7fabc86f7700 mds0.3 beacon_send up:active seq 16750 (currently up:active)
2011-09-01 09:52:12.804684 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16750 rtt 0.001718
2011-09-01 09:52:13.883597 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:13.883625 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:13.884392 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:13.884405 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:13.884414 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:13.884465 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:13.884477 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:13.884490 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:16.803098 7fabc86f7700 mds0.3 beacon_send up:active seq 16751 (currently up:active)
2011-09-01 09:52:16.804348 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16751 rtt 0.001215
2011-09-01 09:52:17.323205 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3009) v1 from client4493
2011-09-01 09:52:18.883800 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:18.883828 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:18.884595 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:18.884608 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:18.884617 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:18.884668 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:18.884668 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:18.884680 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:18.884752 7fabc86f7700 mds0.bal mds0 epoch 6694 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:52:18.884770 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:20.803243 7fabc86f7700 mds0.3 beacon_send up:active seq 16752 (currently up:active)
2011-09-01 09:52:20.804410 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16752 rtt 0.001137
2011-09-01 09:52:23.818624 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3290) v1 from client4469
2011-09-01 09:52:23.865683 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3290) v1 from client4477
2011-09-01 09:52:23.884003 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:23.884028 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:23.884808 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215145 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:23.884822 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:23.884831 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:23.884903 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:23.884924 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:23.884943 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:24.803401 7fabc86f7700 mds0.3 beacon_send up:active seq 16753 (currently up:active)
2011-09-01 09:52:24.804729 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16753 rtt 0.001297
2011-09-01 09:52:26.696271 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3288) v1 from client4481
2011-09-01 09:52:28.803562 7fabc86f7700 mds0.3 beacon_send up:active seq 16754 (currently up:active)
2011-09-01 09:52:28.804864 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16754 rtt 0.001267
2011-09-01 09:52:28.884205 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:28.884230 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:28.885021 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:28.885035 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:28.885044 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:28.885095 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:28.885106 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:28.885179 7fabc86f7700 mds0.bal mds0 epoch 6695 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:52:28.885197 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:32.803730 7fabc86f7700 mds0.3 beacon_send up:active seq 16755 (currently up:active)
2011-09-01 09:52:32.805079 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16755 rtt 0.001297
2011-09-01 09:52:33.884408 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:33.884435 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:33.885229 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:33.885244 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:33.885254 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:33.885306 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:33.885779 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:33.885803 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:36.803867 7fabc86f7700 mds0.3 beacon_send up:active seq 16756 (currently up:active)
2011-09-01 09:52:36.805232 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16756 rtt 0.001323
2011-09-01 09:52:37.325345 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3010) v1 from client4493
2011-09-01 09:52:38.884609 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:38.884635 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:38.885640 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215136 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:38.885665 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:38.885678 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:38.885745 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:38.885765 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:38.885845 7fabc86f7700 mds0.bal mds0 epoch 6696 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:52:38.885863 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:40.804043 7fabc86f7700 mds0.3 beacon_send up:active seq 16757 (currently up:active)
2011-09-01 09:52:40.805399 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16757 rtt 0.001323
2011-09-01 09:52:43.820775 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3291) v1 from client4469
2011-09-01 09:52:43.868307 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3291) v1 from client4477
2011-09-01 09:52:43.884811 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:43.884833 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:43.885683 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215145 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:43.885699 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:43.885708 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:43.885780 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:43.885795 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:43.885808 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:44.804205 7fabc86f7700 mds0.3 beacon_send up:active seq 16758 (currently up:active)
2011-09-01 09:52:44.805465 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16758 rtt 0.001228
2011-09-01 09:52:46.698766 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3289) v1 from client4481
2011-09-01 09:52:48.804364 7fabc86f7700 mds0.3 beacon_send up:active seq 16759 (currently up:active)
2011-09-01 09:52:48.805638 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16759 rtt 0.001240
2011-09-01 09:52:48.885012 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:48.885036 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:48.885815 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:48.885828 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:48.885837 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:48.885888 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:48.885900 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:48.885972 7fabc86f7700 mds0.bal mds0 epoch 6697 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:52:48.885990 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:52.804528 7fabc86f7700 mds0.3 beacon_send up:active seq 16760 (currently up:active)
2011-09-01 09:52:52.805827 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16760 rtt 0.001263
2011-09-01 09:52:53.885171 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:53.885276 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:53.886055 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:53.886069 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:53.886078 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:53.886128 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:53.886140 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:53.886153 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:52:56.804697 7fabc86f7700 mds0.3 beacon_send up:active seq 16761 (currently up:active)
2011-09-01 09:52:56.805972 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16761 rtt 0.001241
2011-09-01 09:52:57.327395 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3011) v1 from client4493
2011-09-01 09:52:58.885374 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:52:58.885403 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:52:58.886173 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:52:58.886186 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:52:58.886195 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:52:58.886246 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:52:58.886257 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:52:58.886329 7fabc86f7700 mds0.bal mds0 epoch 6698 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:52:58.886346 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:00.804860 7fabc86f7700 mds0.3 beacon_send up:active seq 16762 (currently up:active)
2011-09-01 09:53:00.806124 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16762 rtt 0.001216
2011-09-01 09:53:03.822897 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3292) v1 from client4469
2011-09-01 09:53:03.870252 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3292) v1 from client4477
2011-09-01 09:53:03.885552 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:03.885576 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:03.886357 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215146 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:03.886371 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:03.886380 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:03.886433 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:03.886444 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:03.886456 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:04.805002 7fabc86f7700 mds0.3 beacon_send up:active seq 16763 (currently up:active)
2011-09-01 09:53:04.806253 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16763 rtt 0.001216
2011-09-01 09:53:06.701070 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3290) v1 from client4481
2011-09-01 09:53:08.805169 7fabc86f7700 mds0.3 beacon_send up:active seq 16764 (currently up:active)
2011-09-01 09:53:08.806480 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16764 rtt 0.001279
2011-09-01 09:53:08.885731 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:08.885758 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:08.886531 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:08.886546 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:08.886555 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:08.886607 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:08.886619 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:08.886693 7fabc86f7700 mds0.bal mds0 epoch 6699 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:53:08.886711 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:12.805309 7fabc86f7700 mds0.3 beacon_send up:active seq 16765 (currently up:active)
2011-09-01 09:53:12.806606 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16765 rtt 0.001262
2011-09-01 09:53:13.885909 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:13.885937 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:13.886731 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:13.886746 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:13.886755 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:13.886807 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:13.886819 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:13.886833 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:16.805456 7fabc86f7700 mds0.3 beacon_send up:active seq 16766 (currently up:active)
2011-09-01 09:53:16.806785 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16766 rtt 0.001294
2011-09-01 09:53:18.886088 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:18.886118 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:18.886892 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:18.886907 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:18.886916 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:18.886967 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:18.886980 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:18.887053 7fabc86f7700 mds0.bal mds0 epoch 6700 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:53:18.887072 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:20.805595 7fabc86f7700 mds0.3 beacon_send up:active seq 16767 (currently up:active)
2011-09-01 09:53:20.806860 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16767 rtt 0.001232
2011-09-01 09:53:23.824997 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3293) v1 from client4469
2011-09-01 09:53:23.872467 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3293) v1 from client4477
2011-09-01 09:53:23.886264 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:23.886290 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:23.887071 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215146 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:23.887086 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:23.887108 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:23.887161 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:23.887173 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:23.887184 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:24.805755 7fabc86f7700 mds0.3 beacon_send up:active seq 16768 (currently up:active)
2011-09-01 09:53:24.807104 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16768 rtt 0.001318
2011-09-01 09:53:26.703356 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3291) v1 from client4481
2011-09-01 09:53:28.805920 7fabc86f7700 mds0.3 beacon_send up:active seq 16769 (currently up:active)
2011-09-01 09:53:28.807187 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16769 rtt 0.001234
2011-09-01 09:53:28.886465 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:28.886490 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:28.887261 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:28.887275 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:28.887284 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:28.887335 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:28.887347 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:28.887420 7fabc86f7700 mds0.bal mds0 epoch 6701 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:53:28.887438 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:32.806090 7fabc86f7700 mds0.3 beacon_send up:active seq 16770 (currently up:active)
2011-09-01 09:53:32.807348 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16770 rtt 0.001222
2011-09-01 09:53:33.886670 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:33.886698 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:33.887471 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:33.887485 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:33.887494 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:33.887568 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:33.887580 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:33.887593 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:36.806258 7fabc86f7700 mds0.3 beacon_send up:active seq 16771 (currently up:active)
2011-09-01 09:53:36.807460 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16771 rtt 0.001168
2011-09-01 09:53:38.886848 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:38.886877 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:38.887648 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:38.887662 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:38.887670 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:38.887720 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:38.887732 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:38.887805 7fabc86f7700 mds0.bal mds0 epoch 6702 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:53:38.887834 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:40.806420 7fabc86f7700 mds0.3 beacon_send up:active seq 16772 (currently up:active)
2011-09-01 09:53:43.827091 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3294) v1 from client4469
2011-09-01 09:53:43.874825 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3294) v1 from client4477
2011-09-01 09:53:43.887033 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:43.887059 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:43.888321 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215146 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:43.888337 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:43.888347 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:43.888400 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:43.888412 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:43.888425 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:44.808044 7fabc86f7700 mds0.3 beacon_send up:active seq 16773 (currently up:active)
2011-09-01 09:53:44.809555 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16773 rtt 0.001478
2011-09-01 09:53:46.705774 7fabc97fa700 mds0.server handle_client_session client_session(request_renewcaps seq 3292) v1 from client4481
2011-09-01 09:53:48.808184 7fabc86f7700 mds0.3 beacon_send up:active seq 16774 (currently up:active)
2011-09-01 09:53:48.809394 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16774 rtt 0.001176
2011-09-01 09:53:48.887209 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:48.887234 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:48.888005 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:48.888020 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:48.888030 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:48.888081 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:48.888094 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:48.888167 7fabc86f7700 mds0.bal mds0 epoch 6703 load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0>
2011-09-01 09:53:48.888186 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:52.808314 7fabc86f7700 mds0.3 beacon_send up:active seq 16775 (currently up:active)
2011-09-01 09:53:52.809653 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16775 rtt 0.001303
2011-09-01 09:53:53.887412 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:53.887441 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:53.888212 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:53.888227 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:53.888237 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:53.888289 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:53.888302 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:53.888316 7fabc86f7700 mds0.snap check_osd_map - version unchanged
2011-09-01 09:53:56.808482 7fabc86f7700 mds0.3 beacon_send up:active seq 16776 (currently up:active)
2011-09-01 09:53:56.809858 7fabc97fa700 mds0.3 handle_mds_beacon up:active seq 16776 rtt 0.001326
2011-09-01 09:53:58.887592 7fabc86f7700 mds0.cache trim max=100000 cur=42707
2011-09-01 09:53:58.887620 7fabc86f7700 mds0.cache trim_client_leases
2011-09-01 09:53:58.888418 7fabc86f7700 mds0.cache check_memory_usage total 584716, rss 383376, heap 168356, malloc 215137 mmap 0, baseline 146016, buffers 0, max 1048576, 28523 / 41612 inodes have caps, 51593 caps, 1.23986 caps per inode
2011-09-01 09:53:58.888432 7fabc86f7700 mds0.log trim 30 / 30 segments, 28356 / -1 events, 0 (0) expiring, 0 (0) expired
2011-09-01 09:53:58.888440 7fabc86f7700 mds0.log _trim_expired_segments waiting for 2889875850 to expire
2011-09-01 09:53:58.888492 7fabc86f7700 mds0.locker scatter_tick
2011-09-01 09:53:58.888504 7fabc86f7700 mds0.server find_idle_sessions. laggy until 0.000000
2011-09-01 09:53:58.888522 7fabc86f7700 mds0.server new stale session client4493 192.168.101.12:6817/30861 last 2011-09-01 09:52:57.327417
2011-09-01 09:53:58.888531 7fabc86f7700 mds0.locker revoke_stale_caps for client4493
2011-09-01 09:53:58.896116 7fabc86f7700 mds0.locker revoking pAsLsXsFs on [inode 1 [...2,head] / auth v22664 ap=1+0 snaprealm=0x1e04d80 f(v1 m2011-09-01 08:46:09.063242 3=0+3) n(v2851 rc2011-09-01 09:30:10.012956 b319485164835 40186=39732+454)/n(v0 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/@133,4477=pAsLsXs/-@6,4481=pAsLsXsFs/-@6126,4493=pAsLsXsFs/-@826} | lock pastsnapparent dirfrag caps dirty authpin 0x1e09860]
2011-09-01 09:53:58.896257 7fabc86f7700 mds0.locker eval 2496 [inode 1 [...2,head] / auth v22664 ap=1+0 snaprealm=0x1e04d80 f(v1 m2011-09-01 08:46:09.063242 3=0+3) n(v2851 rc2011-09-01 09:30:10.012956 b319485164835 40186=39732+454)/n(v0 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@133,4477=pAsLsXs/-@6,4481=pAsLsXsFs/-@6126,4493=-/-@827} | lock pastsnapparent dirfrag caps dirty authpin 0x1e09860]
2011-09-01 09:53:58.896271 7fabc86f7700 mds0.locker eval doesn't want loner
2011-09-01 09:53:58.896394 7fabc86f7700 mds0.locker file_eval wanted= loner_wanted= other_wanted= filelock=(ifile sync) on [inode 1 [...2,head] / auth v22664 ap=1+0 snaprealm=0x1e04d80 f(v1 m2011-09-01 08:46:09.063242 3=0+3) n(v2851 rc2011-09-01 09:30:10.012956 b319485164835 40186=39732+454)/n(v0 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@133,4477=pAsLsXs/-@6,4481=pAsLsXsFs/-@6126,4493=-/-@827} | lock pastsnapparent dirfrag caps dirty authpin 0x1e09860]
2011-09-01 09:53:58.896514 7fabc86f7700 mds0.locker simple_eval (iauth sync) on [inode 1 [...2,head] / auth v22664 ap=1+0 snaprealm=0x1e04d80 f(v1 m2011-09-01 08:46:09.063242 3=0+3) n(v2851 rc2011-09-01 09:30:10.012956 b319485164835 40186=39732+454)/n(v0 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@133,4477=pAsLsXs/-@6,4481=pAsLsXsFs/-@6126,4493=-/-@827} | lock pastsnapparent dirfrag caps dirty authpin 0x1e09860]
2011-09-01 09:53:58.896641 7fabc86f7700 mds0.locker simple_eval (ilink sync) on [inode 1 [...2,head] / auth v22664 ap=1+0 snaprealm=0x1e04d80 f(v1 m2011-09-01 08:46:09.063242 3=0+3) n(v2851 rc2011-09-01 09:30:10.012956 b319485164835 40186=39732+454)/n(v0 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@133,4477=pAsLsXs/-@6,4481=pAsLsXsFs/-@6126,4493=-/-@827} | lock pastsnapparent dirfrag caps dirty authpin 0x1e09860]
2011-09-01 09:53:58.896764 7fabc86f7700 mds0.locker simple_eval (ixattr sync) on [inode 1 [...2,head] / auth v22664 ap=1+0 snaprealm=0x1e04d80 f(v1 m2011-09-01 08:46:09.063242 3=0+3) n(v2851 rc2011-09-01 09:30:10.012956 b319485164835 40186=39732+454)/n(v0 1=0+1) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@133,4477=pAsLsXs/-@6,4481=pAsLsXsFs/-@6126,4493=-/-@827} | lock pastsnapparent dirfrag caps dirty authpin 0x1e09860]
2011-09-01 09:53:58.896776 7fabc86f7700 mds0.locker eval done
2011-09-01 09:53:58.896816 7fabc86f7700 mds0.locker revoking pAsLsXsFs on [inode 10000000159 [...2,head] /data/ auth v52715 ap=1+1 f(v1 m2011-08-31 11:25:56.970349 7=0+7) n(v2875 rc2011-09-01 09:30:10.012956 b313703226712 39794=39379+415) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@1,4481=pAsLsXsFs/-@13,4493=pAsLsXsFs/-@5} | lock dirfrag caps dirty authpin 0x1e0a0c0]
2011-09-01 09:53:58.896861 7fabc86f7700 mds0.locker eval 2496 [inode 10000000159 [...2,head] /data/ auth v52715 ap=1+1 f(v1 m2011-08-31 11:25:56.970349 7=0+7) n(v2875 rc2011-09-01 09:30:10.012956 b313703226712 39794=39379+415) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@1,4481=pAsLsXsFs/-@13,4493=-/-@6} | lock dirfrag caps dirty authpin 0x1e0a0c0]
2011-09-01 09:53:58.896871 7fabc86f7700 mds0.locker eval doesn't want loner
2011-09-01 09:53:58.896903 7fabc86f7700 mds0.locker file_eval wanted= loner_wanted= other_wanted= filelock=(ifile sync) on [inode 10000000159 [...2,head] /data/ auth v52715 ap=1+1 f(v1 m2011-08-31 11:25:56.970349 7=0+7) n(v2875 rc2011-09-01 09:30:10.012956 b313703226712 39794=39379+415) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@1,4481=pAsLsXsFs/-@13,4493=-/-@6} | lock dirfrag caps dirty authpin 0x1e0a0c0]
2011-09-01 09:53:58.896936 7fabc86f7700 mds0.locker simple_eval (iauth sync) on [inode 10000000159 [...2,head] /data/ auth v52715 ap=1+1 f(v1 m2011-08-31 11:25:56.970349 7=0+7) n(v2875 rc2011-09-01 09:30:10.012956 b313703226712 39794=39379+415) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@1,4481=pAsLsXsFs/-@13,4493=-/-@6} | lock dirfrag caps dirty authpin 0x1e0a0c0]
2011-09-01 09:53:58.896971 7fabc86f7700 mds0.locker simple_eval (ilink sync) on [inode 10000000159 [...2,head] /data/ auth v52715 ap=1+1 f(v1 m2011-08-31 11:25:56.970349 7=0+7) n(v2875 rc2011-09-01 09:30:10.012956 b313703226712 39794=39379+415) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@1,4481=pAsLsXsFs/-@13,4493=-/-@6} | lock dirfrag caps dirty authpin 0x1e0a0c0]
2011-09-01 09:53:58.897005 7fabc86f7700 mds0.locker simple_eval (ixattr sync) on [inode 10000000159 [...2,head] /data/ auth v52715 ap=1+1 f(v1 m2011-08-31 11:25:56.970349 7=0+7) n(v2875 rc2011-09-01 09:30:10.012956 b313703226712 39794=39379+415) (isnap sync r=1) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@1,4481=pAsLsXsFs/-@13,4493=-/-@6} | lock dirfrag caps dirty authpin 0x1e0a0c0]
2011-09-01 09:53:58.897015 7fabc86f7700 mds0.locker eval done
2011-09-01 09:53:58.897050 7fabc86f7700 mds0.locker revoking pAsLsXsFs on [inode 10000000000 [...2,head] /home/ auth v34665 f(v1 m2011-08-29 16:07:47.818241 2=0+2) n(v237 rc2011-08-31 11:28:33.371925 b5781938123 391=353+38) (inest lock) (iversion lock) caps={4469=pAsLsXsFs/-@9,4477=pAsLsXsFs/-@3,4481=pAsLsXsFs/-@12,4493=pAsLsXsFs/-@5} | dirfrag caps 0x27773a0]
2011-09-01 09:53:58.897081 7fabc86f7700 mds0.locker eval 2496 [inode 10000000000 [...2,head] /home/ auth v34665 f(v1 m2011-08-29 16:07:47.818241 2=0+2) n(v237 rc2011-08-3

Can you 'ceph mds tell 0 dumpcache /tmp/foo' and grep out the inode that the open is blocked on?

I was able to run the active mds in debug mode when a hang occurred. This is the log a few seconds before and after I noticed the hang: http://dl.dropbox.com/u/18702194/log.

Any update on this? Were you able to reproduce?

We're seeing similar hangs again. One thing I didn't mention in my previous posts, we are always adjusting the replication factor (setting data and metadata pools to 3), and uploading a different crushmap that places all osds on the same node into the same bucket. Other than that, we see this on a fresh install (currently using 0.37) by simply doing an rsync with the ceph filesystem as the target. The stack trace shows a getattr->make_request call is not returning.

Some of the hangs we've been seeing on the client may have been related to having two nics on each node. We had seen problems in the past with an osd choosing a random interface for heartbeats, so osds were getting wrongly marked as failed. Using public_addr/cluster_addr fixed those issues, but it looks like a similar problem was occurring on the clients, where a client was randomly choosing an interface to send a request, but the mds was sending responses to previously connected sockets. Using --bind <ip> at mount seems to have resolved many of the hangs we were seeing, but not all. The current client hang is similar to one of the first hangs we saw:

#0 0x00007f418b568bac in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libp
thread.so.0
#1 0x000000000048a264 in Client::wait_on_list(std::list<Cond*, std::allocator<Cond*> >&) (
)
#2 0x00000000004b2723 in Client::get_caps(Inode*, int, int, int*, long) ()
#3 0x00000000004b787c in Client::_write(Fh*, long, unsigned long, char const*) ()
#4 0x00000000004b819a in Client::ll_write(Fh*, long, long, char const*) ()
#5 0x000000000046f19d in ?? ()
#6 0x00007f418b78dc95 in ?? () from /lib/libfuse.so.2
#7 0x00007f418b78bcb5 in fuse_session_loop () from /lib/libfuse.so.2
#8 0x000000000047187d in ceph_fuse_ll_main(Client*, int, char const**, int) ()
#9 0x000000000046c6e9 in main ()