|
2017-08-17 18:00:36.760202 7f792785e700 0 log_channel(cluster) log [DBG] : 3.38c scrub starts
|
|
2017-08-17 18:00:36.862782 7f792785e700 0 log_channel(cluster) log [DBG] : 3.38c scrub ok
|
|
2017-08-17 18:04:17.786590 7f7939882700 0 log_channel(cluster) log [WRN] : 20 slow requests, 5 included below; oldest blocked for > 30.029514 secs
|
|
2017-08-17 18:04:17.786603 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024178 seconds old, received at 2017-08-17 18:03:47.762255: osd_op(client.101548923.0:1437692 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 2457600~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:17.786609 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024044 seconds old, received at 2017-08-17 18:03:47.762390: osd_op(client.101548923.0:1437693 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 2588672~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:17.786614 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.029514 seconds old, received at 2017-08-17 18:03:47.756920: osd_op(client.101548923.0:1437579 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 385024~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently op_applied
|
|
2017-08-17 18:04:17.786619 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.028315 seconds old, received at 2017-08-17 18:03:47.758119: osd_op(client.101548923.0:1437582 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 401408~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:17.786630 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.028186 seconds old, received at 2017-08-17 18:03:47.758248: osd_op(client.101548923.0:1437603 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 999424~24576] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:18.786888 7f7939882700 0 log_channel(cluster) log [WRN] : 22 slow requests, 5 included below; oldest blocked for > 31.029834 secs
|
|
2017-08-17 18:04:18.786902 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.025258 seconds old, received at 2017-08-17 18:03:48.761496: osd_op(client.101548923.0:1437695 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 2600960~12288] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:18.786907 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024490 seconds old, received at 2017-08-17 18:03:48.762264: osd_op(client.101548923.0:1437696 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 2641920~12288] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:18.786912 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 31.027950 seconds old, received at 2017-08-17 18:03:47.758804: osd_op(client.101548923.0:1437623 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1286144~12288] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:18.786916 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 31.027756 seconds old, received at 2017-08-17 18:03:47.758997: osd_op(client.101548923.0:1437624 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1302528~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:18.786921 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 31.027293 seconds old, received at 2017-08-17 18:03:47.759461: osd_op(client.101548923.0:1437648 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1335296~12288] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:19.787331 7f7939882700 0 log_channel(cluster) log [WRN] : 22 slow requests, 5 included below; oldest blocked for > 32.030229 secs
|
|
2017-08-17 18:04:19.787351 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 32.027378 seconds old, received at 2017-08-17 18:03:47.759770: osd_op(client.101548923.0:1437653 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1351680~12288] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:19.787358 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 32.027190 seconds old, received at 2017-08-17 18:03:47.759958: osd_op(client.101548923.0:1437655 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1368064~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:19.787363 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 32.027092 seconds old, received at 2017-08-17 18:03:47.760057: osd_op(client.101548923.0:1437656 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1433600~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:19.787370 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 32.026939 seconds old, received at 2017-08-17 18:03:47.760209: osd_op(client.101548923.0:1437661 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1515520~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:19.787413 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 32.026839 seconds old, received at 2017-08-17 18:03:47.760309: osd_op(client.101548923.0:1437665 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1556480~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:20.787736 7f7939882700 0 log_channel(cluster) log [WRN] : 29 slow requests, 5 included below; oldest blocked for > 33.030662 secs
|
|
2017-08-17 18:04:20.787748 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.025041 seconds old, received at 2017-08-17 18:03:50.762540: osd_op(client.101548923.0:1437702 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 2658304~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:20.787755 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024881 seconds old, received at 2017-08-17 18:03:50.762701: osd_op(client.101548923.0:1437703 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 2748416~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:20.787762 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024441 seconds old, received at 2017-08-17 18:03:50.763141: osd_op(client.101548923.0:1437705 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3014656~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:20.787767 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024143 seconds old, received at 2017-08-17 18:03:50.763438: osd_op(client.101548923.0:1437706 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3031040~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:20.787790 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024057 seconds old, received at 2017-08-17 18:03:50.763524: osd_op(client.101548923.0:1437707 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3129344~8192] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:21.788057 7f7939882700 0 log_channel(cluster) log [WRN] : 17 slow requests, 5 included below; oldest blocked for > 34.027158 secs
|
|
2017-08-17 18:04:21.788070 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 31.024319 seconds old, received at 2017-08-17 18:03:50.763610: osd_op(client.101548923.0:1437708 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3207168~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:21.788075 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 31.024253 seconds old, received at 2017-08-17 18:03:50.763676: osd_op(client.101548923.0:1437709 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3239936~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:21.788080 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024265 seconds old, received at 2017-08-17 18:03:51.763664: osd_op(client.101548923.0:1437713 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3297280~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:21.788086 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.024118 seconds old, received at 2017-08-17 18:03:51.763810: osd_op(client.101548923.0:1437714 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 3309568~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently waiting for rw locks
|
|
2017-08-17 18:04:21.788091 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 34.027158 seconds old, received at 2017-08-17 18:03:47.760771: osd_op(client.101548923.0:1437671 5.249 5:924e3893:::rbd_data.0be90c52858957.000000000000063c:head [stat,write 1814528~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently sub_op_commit_rec from 13
|
|
2017-08-17 18:08:33.750282 7f7930870700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/db_impl_write.cc:684] reusing log 737 from recycle list
|
|
2017-08-17 18:08:33.750420 7f7930870700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/db_impl_write.cc:725] [default] New memtable created with log file: #744. Immutable memtables: 0.
|
|
2017-08-17 18:08:33.812980 7f7921051700 4 rocksdb: (Original Log Time 2017/08/17-18:08:33.750490) [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/db_impl_compaction_flush.cc:1158] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots allowed 1, compaction slots scheduled 1
|
|
2017-08-17 18:08:33.813001 7f7921051700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/flush_job.cc:264] [default] [JOB 30] Flushing memtable with next log file: 744
|
|
2017-08-17 18:08:33.813038 7f7921051700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1502982513813024, "job": 30, "event": "flush_started", "num_memtables": 1, "num_entries": 358195, "num_deletes": 39529, "memory_usage": 260052688}
|
|
2017-08-17 18:08:33.813045 7f7921051700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/flush_job.cc:293] [default] [JOB 30] Level-0 flush table #745: started
|
|
2017-08-17 18:08:33.976264 7f7921051700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1502982513976229, "cf_name": "default", "job": 30, "event": "table_file_creation", "file_number": 745, "file_size": 7008166, "table_properties": {"data_size": 6676821, "index_size": 106272, "filter_size": 224084, "raw_key_size": 4335215, "raw_average_key_size": 51, "raw_value_size": 5291246, "raw_average_value_size": 63, "num_data_blocks": 1641, "num_entries": 83538, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "26347", "kMergeOperands": "3714"}}
|
|
2017-08-17 18:08:33.976286 7f7921051700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/flush_job.cc:319] [default] [JOB 30] Level-0 flush table #745: 7008166 bytes OK
|
|
2017-08-17 18:08:33.990909 7f7921051700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/db_impl_files.cc:242] adding log 742 to recycle list
|
|
2017-08-17 18:08:33.990925 7f7921051700 4 rocksdb: (Original Log Time 2017/08/17-18:08:33.976302) [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/memtable_list.cc:360] [default] Level-0 commit table #745 started
|
|
2017-08-17 18:08:33.990948 7f7921051700 4 rocksdb: (Original Log Time 2017/08/17-18:08:33.990824) [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/memtable_list.cc:383] [default] Level-0 commit table #745: memtable #1 done
|
|
2017-08-17 18:08:33.990968 7f7921051700 4 rocksdb: (Original Log Time 2017/08/17-18:08:33.990847) EVENT_LOG_v1 {"time_micros": 1502982513990837, "job": 30, "event": "flush_finished", "lsm_state": [2, 3, 0, 0, 0, 0, 0], "immutable_memtables": 0}
|
|
2017-08-17 18:08:33.990973 7f7921051700 4 rocksdb: (Original Log Time 2017/08/17-18:08:33.990880) [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/db_impl_compaction_flush.cc:132] [default] Level summary: base level 1 max bytes base 268435456 files[2 3 0 0 0 0 0] max score 0.68
|
|
2017-08-17 18:08:33.990987 7f7921051700 4 rocksdb: [/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.1.4/rpm/el7/BUILD/ceph-12.1.4/src/rocksdb/db/db_impl_files.cc:388] [JOB 30] Try to delete WAL files size 251924413, prev total WAL file size 251924425, number of live WAL files 2.
|
|
2017-08-17 18:33:14.015816 7f7939882700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 30.959689 secs
|
|
2017-08-17 18:33:14.015830 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.959689 seconds old, received at 2017-08-17 18:32:43.056053: osd_op(client.96148319.0:518481 3.fa3b0d90 3:09b0dc5f:::rbd_data.bffcbf10b83ca4.000000000000010f:head [stat,write 2949120~8192] snapc 0=[] ack+ondisk+write+known_if_redirected e28759) currently op_applied
|
|
2017-08-17 18:40:17.076176 7f792805f700 0 log_channel(cluster) log [DBG] : 5.7eb scrub starts
|
|
2017-08-17 18:40:17.237002 7f792805f700 0 log_channel(cluster) log [DBG] : 5.7eb scrub ok
|
|
2017-08-17 18:41:30.080755 7f7939882700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 30.914781 secs
|
|
2017-08-17 18:41:30.080785 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.914781 seconds old, received at 2017-08-17 18:40:59.165880: osd_op(client.61379588.0:9054593 3.8987a45a 3:5a25e191:::rbd_data.162c90d3b761c43.0000000000000401:head [stat,write 525312~5120] snapc 4f=[] ack+ondisk+write+known_if_redirected e28759) currently op_applied
|
|
2017-08-17 18:56:03.196893 7f7939882700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 30.676124 secs
|
|
2017-08-17 18:56:03.196915 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.676124 seconds old, received at 2017-08-17 18:55:32.520643: osd_op(client.86267632.0:26918130 5.9dd55ecd 5:b37aabb9:::rbd_data.886e6e7a21c4c4.0000000000000b64:head [write 1204224~4096] snapc 0=[] ack+ondisk+write+known_if_redirected e28759) currently sub_op_commit_rec from 111
|
|
2017-08-17 18:56:06.197467 7f7939882700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 33.676745 secs
|
|
2017-08-17 18:56:06.197480 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.042934 seconds old, received at 2017-08-17 18:55:36.154454: osd_op(client.123160221.0:1653394 5.1d7 5:eb8051c8:::rbd_data.4e24fe2910bfc8.0000000000003785:head [write 3432448~4096] snapc 0=[] ondisk+write+known_if_redirected e28759) currently sub_op_commit_rec from 41
|
|
2017-08-17 18:56:07.197676 7f7939882700 0 log_channel(cluster) log [WRN] : 3 slow requests, 1 included below; oldest blocked for > 34.676957 secs
|
|
2017-08-17 18:56:07.197690 7f7939882700 0 log_channel(cluster) log [WRN] : slow request 30.151070 seconds old, received at 2017-08-17 18:55:37.046530: osd_repop(client.126396492.0:5548396 5.837 e28759/28681 5:ec14da05:::rbd_data.6dc5615f16fd4e.0000000000000e05:head v 28759'3437812) currently started
|
|
2017-08-17 18:57:41.809085 7f793d042700 0 -- 172.28.6.3:6853/15777 >> 172.28.6.4:6804/28227 conn(0x7f796991a800 :6853 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_msg accept connect_seq 37 vs existing csq=37 existing_state=STATE_STANDBY
|
|
2017-08-17 18:57:41.809403 7f793d042700 0 -- 172.28.6.3:6853/15777 >> 172.28.6.4:6804/28227 conn(0x7f796991a800 :6853 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_msg accept connect_seq 38 vs existing csq=37 existing_state=STATE_STANDBY
|