Hi,
we are also experiencing this type of behavior for some weeks on our not
so performance critical hdd pools.
We haven't spent so much time on this problem, because there are
currently more important tasks - but here are a few details:
Running the following loop results in the following output:
while true; do ceph health|grep -q HEALTH_OK || (date; ceph health
detail); sleep 2; done
Sun Sep 2 20:59:47 CEST 2018
HEALTH_WARN 4 slow requests are blocked > 32 sec
REQUEST_SLOW 4 slow requests are blocked > 32 sec
4 ops are blocked > 32.768 sec
osd.43 has blocked requests > 32.768 sec
Sun Sep 2 20:59:50 CEST 2018
HEALTH_WARN 4 slow requests are blocked > 32 sec
REQUEST_SLOW 4 slow requests are blocked > 32 sec
4 ops are blocked > 32.768 sec
osd.43 has blocked requests > 32.768 sec
Sun Sep 2 20:59:52 CEST 2018
HEALTH_OK
Sun Sep 2 21:00:28 CEST 2018
HEALTH_WARN 1 slow requests are blocked > 32 sec
REQUEST_SLOW 1 slow requests are blocked > 32 sec
1 ops are blocked > 32.768 sec
osd.41 has blocked requests > 32.768 sec
Sun Sep 2 21:00:31 CEST 2018
HEALTH_WARN 7 slow requests are blocked > 32 sec
REQUEST_SLOW 7 slow requests are blocked > 32 sec
7 ops are blocked > 32.768 sec
osds 35,41 have blocked requests > 32.768 sec
Sun Sep 2 21:00:33 CEST 2018
HEALTH_WARN 7 slow requests are blocked > 32 sec
REQUEST_SLOW 7 slow requests are blocked > 32 sec
7 ops are blocked > 32.768 sec
osds 35,51 have blocked requests > 32.768 sec
Sun Sep 2 21:00:35 CEST 2018
HEALTH_WARN 7 slow requests are blocked > 32 sec
REQUEST_SLOW 7 slow requests are blocked > 32 sec
7 ops are blocked > 32.768 sec
osds 35,51 have blocked requests > 32.768 sec
Our details:
* system details:
* Ubuntu 16.04
* Kernel 4.13.0-39
* 30 * 8 TB Disk (SEAGATE/ST8000NM0075)
* 3* Dell Power Edge R730xd (Firmware 2.50.50.50)
* Intel(R) Xeon(R) CPU E5-2680 v4 @ 2.40GHz
* 2*10GBITS SFP+ Network Adapters
* 192GB RAM
* Pools are using replication factor 3, 2MB object size,
85% write load, 1700 write IOPS/sec
(ops mainly between 4k and 16k size), 300 read IOPS/sec
* we have the impression that this appears on deepscrub/scrub activity.
* Ceph 12.2.5, we alread played with the osd settings OSD Settings
(our assumtion was that the problem is related to rocksdb compaction)
bluestore cache kv max = 2147483648
bluestore cache kv ratio = 0.9
bluestore cache meta ratio = 0.1
bluestore cache size hdd = 10737418240
* this type problem only appears on hdd/bluestore osds, ssd/bluestore
osds did never experienced that problem
* the system is healthy, no swapping, no high load, no errors in dmesg
I attached a log excerpt of osd.35 - probably this is useful for
investigating the problem is someone owns deeper bluestore knowledge.
(slow requests appeared on Sun Sep 2 21:00:35)
Regards
Marc
Am 02.09.2018 um 15:50 schrieb Brett Chancellor:
> The warnings look like this.
>
> 6 ops are blocked > 32.768 sec on osd.219
> 1 osds have slow requests
>
> On Sun, Sep 2, 2018, 8:45 AM Alfredo Deza <adeza@xxxxxxxxxx
> <mailto:adeza@xxxxxxxxxx>> wrote:
>
> On Sat, Sep 1, 2018 at 12:45 PM, Brett Chancellor
> <bchancellor@xxxxxxxxxxxxxx <mailto:bchancellor@xxxxxxxxxxxxxx>>
> wrote:
> > Hi Cephers,
> > I am in the process of upgrading a cluster from Filestore to
> bluestore,
> > but I'm concerned about frequent warnings popping up against the new
> > bluestore devices. I'm frequently seeing messages like this,
> although the
> > specific osd changes, it's always one of the few hosts I've
> converted to
> > bluestore.
> >
> > 6 ops are blocked > 32.768 sec on osd.219
> > 1 osds have slow requests
> >
> > I'm running 12.2.4, have any of you seen similar issues? It
> seems as though
> > these messages pop up more frequently when one of the bluestore
> pgs is
> > involved in a scrub. I'll include my bluestore creation process
> below, in
> > case that might cause an issue. (sdb, sdc, sdd are SATA, sde and
> sdf are
> > SSD)
>
> Would be useful to include what those warnings say. The ceph-volume
> commands look OK to me
>
> >
> >
> > ## Process used to create osds
> > sudo ceph-disk zap /dev/sdb /dev/sdc /dev/sdd /dev/sdd /dev/sde
> /dev/sdf
> > sudo ceph-volume lvm zap /dev/sdb
> > sudo ceph-volume lvm zap /dev/sdc
> > sudo ceph-volume lvm zap /dev/sdd
> > sudo ceph-volume lvm zap /dev/sde
> > sudo ceph-volume lvm zap /dev/sdf
> > sudo sgdisk -n 0:2048:+133GiB -t 0:FFFF -c 1:"ceph block.db sdb"
> /dev/sdf
> > sudo sgdisk -n 0:0:+133GiB -t 0:FFFF -c 2:"ceph block.db sdc"
> /dev/sdf
> > sudo sgdisk -n 0:0:+133GiB -t 0:FFFF -c 3:"ceph block.db sdd"
> /dev/sdf
> > sudo sgdisk -n 0:0:+133GiB -t 0:FFFF -c 4:"ceph block.db sde"
> /dev/sdf
> > sudo ceph-volume lvm create --bluestore --crush-device-class hdd
> --data
> > /dev/sdb --block.db /dev/sdf1
> > sudo ceph-volume lvm create --bluestore --crush-device-class hdd
> --data
> > /dev/sdc --block.db /dev/sdf2
> > sudo ceph-volume lvm create --bluestore --crush-device-class hdd
> --data
> > /dev/sdd --block.db /dev/sdf3
> >
> >
> > _______________________________________________
> > ceph-users mailing list
> > ceph-users@xxxxxxxxxxxxxx <mailto:ceph-users@xxxxxxxxxxxxxx>
> > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
> >
>
>
>
> _______________________________________________
> ceph-users mailing list
> ceph-users@xxxxxxxxxxxxxx
> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
2018-09-02 20:48:10.132941 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:388] [JOB 7550] Try to delete WAL files size 257470295, prev total WAL file size 257689109, number of live WAL files 2.
2018-09-02 20:53:06.663507 7fef5d22a700 0 log_channel(cluster) log [DBG] : 34.24a deep-scrub starts
2018-09-02 20:53:29.645506 7fef6523a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_write.cc:684] reusing log 87465 from recycle list
2018-09-02 20:53:29.645647 7fef6523a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_write.cc:725] [default] New memtable created with log file: #87469. Immutable memtables: 0.
2018-09-02 20:53:29.657867 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:53:29.645769) [/build/ceph-12.2.5/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
2018-09-02 20:53:29.657895 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:264] [default] [JOB 7551] Flushing memtable with next log file: 87469
2018-09-02 20:53:29.657932 7fef55a1b700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914409657914, "job": 7551, "event": "flush_started", "num_memtables": 1, "num_entries": 119724, "num_deletes": 29838, "memory_usage": 260129656}
2018-09-02 20:53:29.657961 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:293] [default] [JOB 7551] Level-0 flush table #87470: started
2018-09-02 20:53:29.983831 7fef55a1b700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914409983810, "cf_name": "default", "job": 7551, "event": "table_file_creation", "file_number": 87470, "file_size": 9289373, "table_properties": {"data_size": 9044797, "index_size": 101686, "filter_size": 141901, "raw_key_size": 2650118, "raw_average_key_size": 54, "raw_value_size": 8169523, "raw_average_value_size": 167, "num_data_blocks": 1422, "num_entries": 48841, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "23129", "kMergeOperands": "133"}}
2018-09-02 20:53:29.983852 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:319] [default] [JOB 7551] Level-0 flush table #87470: 9289373 bytes OK
2018-09-02 20:53:29.985411 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:242] adding log 87467 to recycle list
2018-09-02 20:53:29.985427 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:53:29.983865) [/build/ceph-12.2.5/src/rocksdb/db/memtable_list.cc:360] [default] Level-0 commit table #87470 started
2018-09-02 20:53:29.985432 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:53:29.985299) [/build/ceph-12.2.5/src/rocksdb/db/memtable_list.cc:383] [default] Level-0 commit table #87470: memtable #1 done
2018-09-02 20:53:29.985435 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:53:29.985318) EVENT_LOG_v1 {"time_micros": 1535914409985311, "job": 7551, "event": "flush_finished", "lsm_state": [3, 5, 38, 65, 0, 0, 0], "immutable_memtables": 0}
2018-09-02 20:53:29.985438 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:53:29.985377) [/build/ceph-12.2.5/src/rocksdb/db/db_impl_compaction_flush.cc:132] [default] Level summary: base level 1 max bytes base 268435456 files[3 5 38 65 0 0 0] max score 1.00
2018-09-02 20:53:29.985481 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:388] [JOB 7551] Try to delete WAL files size 257670240, prev total WAL file size 259168109, number of live WAL files 2.
2018-09-02 20:58:51.766025 7fef6523a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_write.cc:684] reusing log 87467 from recycle list
2018-09-02 20:58:51.766167 7fef6523a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_write.cc:725] [default] New memtable created with log file: #87471. Immutable memtables: 0.
2018-09-02 20:58:51.766283 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_compaction_flush.cc:49] [JOB 7552] Syncing log #87469
2018-09-02 20:58:51.767035 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:58:51.766243) [/build/ceph-12.2.5/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
2018-09-02 20:58:51.767051 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:264] [default] [JOB 7552] Flushing memtable with next log file: 87471
2018-09-02 20:58:51.767075 7fef55a1b700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914731767064, "job": 7552, "event": "flush_started", "num_memtables": 1, "num_entries": 123787, "num_deletes": 31959, "memory_usage": 260072792}
2018-09-02 20:58:51.767082 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:293] [default] [JOB 7552] Level-0 flush table #87472: started
2018-09-02 20:58:52.755937 7fef55a1b700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914732755915, "cf_name": "default", "job": 7552, "event": "table_file_creation", "file_number": 87472, "file_size": 11770987, "table_properties": {"data_size": 11503679, "index_size": 110067, "filter_size": 156253, "raw_key_size": 2849159, "raw_average_key_size": 54, "raw_value_size": 10562231, "raw_average_value_size": 201, "num_data_blocks": 1555, "num_entries": 52421, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "25127", "kMergeOperands": "112"}}
2018-09-02 20:58:52.755959 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:319] [default] [JOB 7552] Level-0 flush table #87472: 11770987 bytes OK
2018-09-02 20:58:52.757442 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:242] adding log 87469 to recycle list
2018-09-02 20:58:52.757456 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:58:52.755973) [/build/ceph-12.2.5/src/rocksdb/db/memtable_list.cc:360] [default] Level-0 commit table #87472 started
2018-09-02 20:58:52.757463 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:58:52.757339) [/build/ceph-12.2.5/src/rocksdb/db/memtable_list.cc:383] [default] Level-0 commit table #87472: memtable #1 done
2018-09-02 20:58:52.757466 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:58:52.757359) EVENT_LOG_v1 {"time_micros": 1535914732757352, "job": 7552, "event": "flush_finished", "lsm_state": [4, 5, 38, 65, 0, 0, 0], "immutable_memtables": 0}
2018-09-02 20:58:52.757471 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-20:58:52.757418) [/build/ceph-12.2.5/src/rocksdb/db/db_impl_compaction_flush.cc:132] [default] Level summary: base level 1 max bytes base 268435456 files[4 5 38 65 0 0 0] max score 1.00
2018-09-02 20:58:52.757509 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:388] [JOB 7552] Try to delete WAL files size 257481253, prev total WAL file size 258814419, number of live WAL files 2.
2018-09-02 20:58:52.758043 7fef5521a700 3 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl.cc:447] ------- DUMPING STATS -------
2018-09-02 20:58:52.758059 7fef5521a700 3 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl.cc:448]
** DB Stats **
Uptime(secs): 1656752.4 total, 1337.7 interval
Cumulative writes: 116M writes, 844M keys, 116M commit groups, 1.0 writes per commit group, ingest: 1314.16 GB, 0.81 MB/s
Cumulative WAL: 116M writes, 50M syncs, 2.30 writes per sync, written: 1314.16 GB, 0.81 MB/s
Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent
Interval writes: 79K writes, 503K keys, 79K commit groups, 1.0 writes per commit group, ingest: 978.25 MB, 0.73 MB/s
Interval WAL: 79K writes, 33K syncs, 2.37 writes per sync, written: 0.96 MB, 0.73 MB/s
Interval stall: 00:00:0.000 H:M:S, 0.0 percent
** Compaction Stats [default] **
Level Files Size Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
----------------------------------------------------------------------------------------------------------------------------------------------------------
L0 4/0 39.48 MB 1.0 0.0 0.0 0.0 65.0 65.0 0.0 1.0 0.0 36.9 1801 5496 0.328 0 0
L1 5/0 237.62 MB 1.0 303.6 64.9 238.7 267.3 28.7 0.0 4.1 27.3 24.1 11376 1373 8.286 2534M 67M
L2 38/0 2.18 GB 1.0 299.3 27.8 271.5 286.5 15.0 0.9 10.3 30.0 28.7 10232 430 23.795 1073M 38M
L3 65/0 3.62 GB 0.1 109.5 16.0 93.5 94.3 0.8 0.0 5.9 32.6 28.0 3442 239 14.403 498M 216M
Sum 112/0 6.06 GB 0.0 712.4 108.7 603.7 713.0 109.4 0.9 11.0 27.2 27.2 26852 7538 3.562 4106M 322M
Int 0/0 0.00 KB 0.0 0.3 0.1 0.2 0.3 0.1 0.0 7.0 13.5 14.1 20 5 3.935 1954K 34K
Uptime(secs): 1656752.4 total, 1656752.4 interval
Flush(GB): cumulative 64.961, interval 0.039
AddFile(GB): cumulative 0.000, interval 0.000
AddFile(Total Files): cumulative 0, interval 0
AddFile(L0 Files): cumulative 0, interval 0
AddFile(Keys): cumulative 0, interval 0
Cumulative compaction: 713.04 GB write, 0.44 MB/s write, 712.39 GB read, 0.44 MB/s read, 26851.8 seconds
Interval compaction: 0.27 GB write, 0.00 MB/s write, 0.26 GB read, 0.00 MB/s read, 19.7 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count
** File Read Latency Histogram By Level [default] **
** Compaction Stats [default] **
Level Files Size Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
----------------------------------------------------------------------------------------------------------------------------------------------------------
L0 4/0 39.48 MB 1.0 0.0 0.0 0.0 65.0 65.0 0.0 1.0 0.0 36.9 1801 5496 0.328 0 0
L1 5/0 237.62 MB 1.0 303.6 64.9 238.7 267.3 28.7 0.0 4.1 27.3 24.1 11376 1373 8.286 2534M 67M
L2 38/0 2.18 GB 1.0 299.3 27.8 271.5 286.5 15.0 0.9 10.3 30.0 28.7 10232 430 23.795 1073M 38M
L3 65/0 3.62 GB 0.1 109.5 16.0 93.5 94.3 0.8 0.0 5.9 32.6 28.0 3442 239 14.403 498M 216M
Sum 112/0 6.06 GB 0.0 712.4 108.7 603.7 713.0 109.4 0.9 11.0 27.2 27.2 26852 7538 3.562 4106M 322M
Int 0/0 0.00 KB 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 0.000 0 0
Uptime(secs): 1656752.4 total, 1656752.4 interval
Flush(GB): cumulative 64.961, interval 0.000
AddFile(GB): cumulative 0.000, interval 0.000
AddFile(Total Files): cumulative 0, interval 0
AddFile(L0 Files): cumulative 0, interval 0
AddFile(Keys): cumulative 0, interval 0
Cumulative compaction: 713.04 GB write, 0.44 MB/s write, 712.39 GB read, 0.44 MB/s read, 26851.8 seconds
Interval compaction: 0.00 GB write, 0.00 MB/s write, 0.00 GB read, 0.00 MB/s read, 0.0 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count
** File Read Latency Histogram By Level [default] **
2018-09-02 20:58:52.758211 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1403] [default] [JOB 7553] Compacting 4@0 + 5@1 files to L1, score 1.00
2018-09-02 20:58:52.758233 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1407] [default] Compaction start summary: Base version 7552 Base level 0, inputs: [87472(11MB) 87470(9071KB) 87468(8949KB) 87466(10MB)], [87460(65MB) 87461(13MB) 87462(64MB) 87463(65MB) 87464(28MB)]
2018-09-02 20:58:52.758259 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914732758240, "job": 7553, "event": "compaction_started", "files_L0": [87472, 87470, 87468, 87466], "files_L1": [87460, 87461, 87462, 87463, 87464], "score": 1, "input_data_size": 290554488}
2018-09-02 20:58:59.585323 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7553] Generated table #87473: 538382 keys, 69374720 bytes
2018-09-02 20:58:59.585356 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914739585341, "cf_name": "default", "job": 7553, "event": "table_file_creation", "file_number": 87473, "file_size": 69374720, "table_properties": {"data_size": 67137839, "index_size": 743689, "filter_size": 1492204, "raw_key_size": 29092625, "raw_average_key_size": 54, "raw_value_size": 58152988, "raw_average_value_size": 108, "num_data_blocks": 10887, "num_entries": 538382, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "302709", "kMergeOperands": "0"}}
2018-09-02 20:59:02.903212 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7553] Generated table #87474: 45081 keys, 29617934 bytes
2018-09-02 20:59:02.903250 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914742903232, "cf_name": "default", "job": 7553, "event": "table_file_creation", "file_number": 87474, "file_size": 29617934, "table_properties": {"data_size": 29333008, "index_size": 111231, "filter_size": 172707, "raw_key_size": 3963593, "raw_average_key_size": 87, "raw_value_size": 28368964, "raw_average_value_size": 629, "num_data_blocks": 1207, "num_entries": 45081, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "22446", "kMergeOperands": "0"}}
2018-09-02 20:59:08.490603 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7553] Generated table #87475: 143244 keys, 67981671 bytes
2018-09-02 20:59:08.490638 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914748490622, "cf_name": "default", "job": 7553, "event": "table_file_creation", "file_number": 87475, "file_size": 67981671, "table_properties": {"data_size": 67177015, "index_size": 308493, "filter_size": 495175, "raw_key_size": 12594867, "raw_average_key_size": 87, "raw_value_size": 64160361, "raw_average_value_size": 447, "num_data_blocks": 3307, "num_entries": 143244, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "76282", "kMergeOperands": "0"}}
2018-09-02 20:59:13.377688 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7553] Generated table #87476: 369692 keys, 68509646 bytes
2018-09-02 20:59:13.377723 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914753377707, "cf_name": "default", "job": 7553, "event": "table_file_creation", "file_number": 87476, "file_size": 68509646, "table_properties": {"data_size": 67110623, "index_size": 335548, "filter_size": 1062487, "raw_key_size": 17920095, "raw_average_key_size": 48, "raw_value_size": 61054045, "raw_average_value_size": 165, "num_data_blocks": 4581, "num_entries": 369692, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "103726", "kMergeOperands": "1"}}
2018-09-02 20:59:16.561633 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7553] Generated table #87477: 974035 keys, 29459305 bytes
2018-09-02 20:59:16.561668 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756561652, "cf_name": "default", "job": 7553, "event": "table_file_creation", "file_number": 87477, "file_size": 29459305, "table_properties": {"data_size": 26763386, "index_size": 199231, "filter_size": 2495696, "raw_key_size": 17532630, "raw_average_key_size": 18, "raw_value_size": 13711694, "raw_average_value_size": 14, "num_data_blocks": 6568, "num_entries": 974035, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "199921", "kMergeOperands": "178474"}}
2018-09-02 20:59:16.563357 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1173] [default] [JOB 7553] Compacted 4@0 + 5@1 files to L1 => 264943276 bytes
2018-09-02 20:59:16.573914 7fef5521a700 4 rocksdb: (Original Log Time 2018/09/02-20:59:16.572277) [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:621] [default] compacted to: base level 1 max bytes base 268435456 files[0 5 38 65 0 0 0] max score 1.11, MB/sec: 12.2 rd, 11.1 wr, level 1, files in(4, 5) out(5) MB in(39.5, 237.6) out(252.7), read-write-amplify(13.4) write-amplify(6.4) OK, records in: 2122942, records dropped: 51763
2018-09-02 20:59:16.573929 7fef5521a700 4 rocksdb: (Original Log Time 2018/09/02-20:59:16.572319) EVENT_LOG_v1 {"time_micros": 1535914756572299, "job": 7553, "event": "compaction_finished", "compaction_time_micros": 23805058, "output_level": 1, "num_output_files": 5, "total_output_size": 264943276, "num_input_records": 2122197, "num_output_records": 2070434, "num_subcompactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 5, 38, 65, 0, 0, 0]}
2018-09-02 20:59:16.574031 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574027, "job": 7553, "event": "table_file_deletion", "file_number": 87472}
2018-09-02 20:59:16.574048 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574046, "job": 7553, "event": "table_file_deletion", "file_number": 87470}
2018-09-02 20:59:16.574074 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574073, "job": 7553, "event": "table_file_deletion", "file_number": 87468}
2018-09-02 20:59:16.574089 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574087, "job": 7553, "event": "table_file_deletion", "file_number": 87466}
2018-09-02 20:59:16.574112 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574107, "job": 7553, "event": "table_file_deletion", "file_number": 87464}
2018-09-02 20:59:16.574133 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574130, "job": 7553, "event": "table_file_deletion", "file_number": 87463}
2018-09-02 20:59:16.574157 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574153, "job": 7553, "event": "table_file_deletion", "file_number": 87462}
2018-09-02 20:59:16.574178 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574175, "job": 7553, "event": "table_file_deletion", "file_number": 87461}
2018-09-02 20:59:16.574201 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574198, "job": 7553, "event": "table_file_deletion", "file_number": 87460}
2018-09-02 20:59:16.574281 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1403] [default] [JOB 7554] Compacting 1@1 + 20@2 files to L2, score 1.11
2018-09-02 20:59:16.574301 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1407] [default] Compaction start summary: Base version 7553 Base level 1, inputs: [87473(66MB)], [87421(66MB) 87422(65MB) 87423(49MB) 87424(64MB) 87425(66MB) 87426(65MB) 87427(65MB) 87428(65MB) 87429(65MB) 87430(65MB) 87431(65MB) 87432(65MB) 87433(65MB) 87434(65MB) 87435(65MB) 87436(65MB) 87437(65MB) 87438(65MB) 87439(20MB) 86669(65MB)]
2018-09-02 20:59:16.574322 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914756574308, "job": 7554, "event": "compaction_started", "files_L1": [87473], "files_L2": [87421, 87422, 87423, 87424, 87425, 87426, 87427, 87428, 87429, 87430, 87431, 87432, 87433, 87434, 87435, 87436, 87437, 87438, 87439, 86669], "score": 1.11385, "input_data_size": 1383388740}
2018-09-02 20:59:21.743743 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87478: 937188 keys, 70618693 bytes
2018-09-02 20:59:21.743781 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914761743764, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87478, "file_size": 70618693, "table_properties": {"data_size": 67112685, "index_size": 1011746, "filter_size": 2493272, "raw_key_size": 49521315, "raw_average_key_size": 52, "raw_value_size": 51961449, "raw_average_value_size": 55, "num_data_blocks": 15232, "num_entries": 937188, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "594504", "kMergeOperands": "0"}}
2018-09-02 20:59:25.900347 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87479: 244332 keys, 68865337 bytes
2018-09-02 20:59:25.900384 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914765900366, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87479, "file_size": 68865337, "table_properties": {"data_size": 67112945, "index_size": 994091, "filter_size": 757313, "raw_key_size": 21390256, "raw_average_key_size": 87, "raw_value_size": 61217025, "raw_average_value_size": 250, "num_data_blocks": 11117, "num_entries": 244332, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "144409", "kMergeOperands": "0"}}
2018-09-02 20:59:29.749632 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87480: 214899 keys, 68551721 bytes
2018-09-02 20:59:29.749672 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914769749652, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87480, "file_size": 68551721, "table_properties": {"data_size": 67127107, "index_size": 742503, "filter_size": 681123, "raw_key_size": 18823434, "raw_average_key_size": 87, "raw_value_size": 62038612, "raw_average_value_size": 288, "num_data_blocks": 8549, "num_entries": 214899, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "131048", "kMergeOperands": "0"}}
2018-09-02 20:59:30.708588 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87481: 48832 keys, 16321135 bytes
2018-09-02 20:59:30.708628 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914770708610, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87481, "file_size": 16321135, "table_properties": {"data_size": 16085797, "index_size": 79600, "filter_size": 154750, "raw_key_size": 4294081, "raw_average_key_size": 87, "raw_value_size": 15082259, "raw_average_value_size": 308, "num_data_blocks": 841, "num_entries": 48832, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "27221", "kMergeOperands": "0"}}
2018-09-02 20:59:35.540190 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87482: 197876 keys, 68137454 bytes
2018-09-02 20:59:35.540237 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914775540217, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87482, "file_size": 68137454, "table_properties": {"data_size": 67110640, "index_size": 393504, "filter_size": 632322, "raw_key_size": 17396869, "raw_average_key_size": 87, "raw_value_size": 62947399, "raw_average_value_size": 318, "num_data_blocks": 4215, "num_entries": 197876, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "108667", "kMergeOperands": "0"}}
2018-09-02 20:59:39.515008 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87483: 313210 keys, 69314980 bytes
2018-09-02 20:59:39.515052 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914779515033, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87483, "file_size": 69314980, "table_properties": {"data_size": 67110048, "index_size": 1269464, "filter_size": 934480, "raw_key_size": 27459440, "raw_average_key_size": 87, "raw_value_size": 59157831, "raw_average_value_size": 188, "num_data_blocks": 13882, "num_entries": 313210, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "208516", "kMergeOperands": "0"}}
2018-09-02 20:59:43.643999 7fef5d22a700 -1 osd.35 pg_epoch: 62934 pg[34.24a( v 62934'594690 (62934'593116,62934'594690] local-lis/les=52161/52162 n=9219 ec=42458/9928 lis/c 52161/52161 les/c/f 52162/52162/20475 52161/52161/52133) [35,69,72] r=0 lpr=52161 crt=62934'594690 lcod 62934'594689 mlcod 62934'594689 active+clean+scrubbing+deep] _scan_snaps no head for 34:5262d62f:::rbd_data.216e8874b0dc51.000000000035a26e:102 (have MIN)
2018-09-02 20:59:44.771574 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87484: 208199 keys, 69131331 bytes
2018-09-02 20:59:44.771614 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914784771595, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87484, "file_size": 69131331, "table_properties": {"data_size": 67109977, "index_size": 1346926, "filter_size": 673440, "raw_key_size": 18258722, "raw_average_key_size": 87, "raw_value_size": 61573771, "raw_average_value_size": 295, "num_data_blocks": 14779, "num_entries": 208199, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "96158", "kMergeOperands": "0"}}
2018-09-02 20:59:50.326311 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87485: 238569 keys, 69122237 bytes
2018-09-02 20:59:50.326357 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914790326334, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87485, "file_size": 69122237, "table_properties": {"data_size": 67118041, "index_size": 1255449, "filter_size": 747759, "raw_key_size": 20933477, "raw_average_key_size": 87, "raw_value_size": 61110677, "raw_average_value_size": 256, "num_data_blocks": 13733, "num_entries": 238569, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "130651", "kMergeOperands": "0"}}
2018-09-02 20:59:55.116814 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87486: 141037 keys, 69043569 bytes
2018-09-02 20:59:55.116855 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914795116835, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87486, "file_size": 69043569, "table_properties": {"data_size": 67112421, "index_size": 1422975, "filter_size": 507185, "raw_key_size": 12338891, "raw_average_key_size": 87, "raw_value_size": 62628736, "raw_average_value_size": 444, "num_data_blocks": 15671, "num_entries": 141037, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "25055", "kMergeOperands": "0"}}
2018-09-02 20:59:58.397748 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87487: 114260 keys, 68946202 bytes
2018-09-02 20:59:58.397792 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914798397771, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87487, "file_size": 68946202, "table_properties": {"data_size": 67112458, "index_size": 1393014, "filter_size": 439744, "raw_key_size": 9995435, "raw_average_key_size": 87, "raw_value_size": 63309696, "raw_average_value_size": 554, "num_data_blocks": 15379, "num_entries": 114260, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:02.337375 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87488: 115900 keys, 68950783 bytes
2018-09-02 21:00:02.337418 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914802337398, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87488, "file_size": 68950783, "table_properties": {"data_size": 67113251, "index_size": 1392701, "filter_size": 443845, "raw_key_size": 10139855, "raw_average_key_size": 87, "raw_value_size": 63283928, "raw_average_value_size": 546, "num_data_blocks": 15345, "num_entries": 115900, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:05.601535 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87489: 116665 keys, 68972175 bytes
2018-09-02 21:00:05.601568 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914805601554, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87489, "file_size": 68972175, "table_properties": {"data_size": 67110356, "index_size": 1414522, "filter_size": 446311, "raw_key_size": 10206315, "raw_average_key_size": 87, "raw_value_size": 63242843, "raw_average_value_size": 542, "num_data_blocks": 15583, "num_entries": 116665, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:10.484426 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87490: 116333 keys, 68941979 bytes
2018-09-02 21:00:10.484462 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914810484444, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87490, "file_size": 68941979, "table_properties": {"data_size": 67110498, "index_size": 1385431, "filter_size": 445064, "raw_key_size": 10178489, "raw_average_key_size": 87, "raw_value_size": 63284881, "raw_average_value_size": 543, "num_data_blocks": 15252, "num_entries": 116333, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:19.415867 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87491: 117512 keys, 69007940 bytes
2018-09-02 21:00:19.415915 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914819415895, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87491, "file_size": 69007940, "table_properties": {"data_size": 67111194, "index_size": 1446765, "filter_size": 448995, "raw_key_size": 10279321, "raw_average_key_size": 87, "raw_value_size": 63187874, "raw_average_value_size": 537, "num_data_blocks": 15953, "num_entries": 117512, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:25.476117 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87492: 116479 keys, 68930412 bytes
2018-09-02 21:00:25.476159 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914825476139, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87492, "file_size": 68930412, "table_properties": {"data_size": 67111108, "index_size": 1373104, "filter_size": 445214, "raw_key_size": 10191872, "raw_average_key_size": 87, "raw_value_size": 63297468, "raw_average_value_size": 543, "num_data_blocks": 15120, "num_entries": 116479, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:30.027393 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87493: 116064 keys, 68925391 bytes
2018-09-02 21:00:30.027428 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914830027412, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87493, "file_size": 68925391, "table_properties": {"data_size": 67113319, "index_size": 1367077, "filter_size": 444009, "raw_key_size": 10155642, "raw_average_key_size": 87, "raw_value_size": 63314906, "raw_average_value_size": 545, "num_data_blocks": 15043, "num_entries": 116064, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:35.738507 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87494: 285439 keys, 68430484 bytes
2018-09-02 21:00:35.738547 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914835738530, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87494, "file_size": 68430484, "table_properties": {"data_size": 67110549, "index_size": 466609, "filter_size": 852338, "raw_key_size": 25093982, "raw_average_key_size": 87, "raw_value_size": 61167213, "raw_average_value_size": 214, "num_data_blocks": 5052, "num_entries": 285439, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "197697", "kMergeOperands": "0"}}
2018-09-02 21:00:40.452342 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87495: 121454 keys, 68862489 bytes
2018-09-02 21:00:40.452380 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914840452362, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87495, "file_size": 68862489, "table_properties": {"data_size": 67110303, "index_size": 1295500, "filter_size": 455699, "raw_key_size": 10632547, "raw_average_key_size": 87, "raw_value_size": 63285741, "raw_average_value_size": 521, "num_data_blocks": 14285, "num_entries": 121454, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "9264", "kMergeOperands": "0"}}
2018-09-02 21:00:43.470802 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87496: 115255 keys, 68904161 bytes
2018-09-02 21:00:43.470834 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914843470820, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87496, "file_size": 68904161, "table_properties": {"data_size": 67113226, "index_size": 1348149, "filter_size": 441800, "raw_key_size": 10085305, "raw_average_key_size": 87, "raw_value_size": 63351237, "raw_average_value_size": 549, "num_data_blocks": 14849, "num_entries": 115255, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:48.009021 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87497: 116917 keys, 68968830 bytes
2018-09-02 21:00:48.009065 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914848009047, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87497, "file_size": 68968830, "table_properties": {"data_size": 67111105, "index_size": 1409939, "filter_size": 446800, "raw_key_size": 10228586, "raw_average_key_size": 87, "raw_value_size": 63242610, "raw_average_value_size": 540, "num_data_blocks": 15541, "num_entries": 116917, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:49.701817 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7554] Generated table #87498: 18250 keys, 10843640 bytes
2018-09-02 21:00:49.701855 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849701836, "cf_name": "default", "job": 7554, "event": "table_file_creation", "file_number": 87498, "file_size": 10843640, "table_properties": {"data_size": 10554876, "index_size": 217842, "filter_size": 69937, "raw_key_size": 1596745, "raw_average_key_size": 87, "raw_value_size": 9954011, "raw_average_value_size": 545, "num_data_blocks": 2403, "num_entries": 18250, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:00:49.702035 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1173] [default] [JOB 7554] Compacted 1@1 + 20@2 files to L2 => 1337790943 bytes
2018-09-02 21:00:49.711132 7fef5521a700 4 rocksdb: (Original Log Time 2018/09/02-21:00:49.703803) [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:621] [default] compacted to: base level 1 max bytes base 268435456 files[0 4 39 65 0 0 0] max score 1.01, MB/sec: 14.9 rd, 14.4 wr, level 2, files in(1, 20) out(21) MB in(66.2, 1253.1) out(1275.8), read-write-amplify(39.2) write-amplify(19.3) OK, records in: 4155081, records dropped: 140390
2018-09-02 21:00:49.711162 7fef5521a700 4 rocksdb: (Original Log Time 2018/09/02-21:00:49.703868) EVENT_LOG_v1 {"time_micros": 1535914849703824, "job": 7554, "event": "compaction_finished", "compaction_time_micros": 93127608, "output_level": 2, "num_output_files": 21, "total_output_size": 1337790943, "num_input_records": 4155060, "num_output_records": 4014670, "num_subcompactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 4, 39, 65, 0, 0, 0]}
2018-09-02 21:00:49.711318 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711311, "job": 7554, "event": "table_file_deletion", "file_number": 87473}
2018-09-02 21:00:49.711349 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711346, "job": 7554, "event": "table_file_deletion", "file_number": 87439}
2018-09-02 21:00:49.711390 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711386, "job": 7554, "event": "table_file_deletion", "file_number": 87438}
2018-09-02 21:00:49.711412 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711408, "job": 7554, "event": "table_file_deletion", "file_number": 87437}
2018-09-02 21:00:49.711450 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711448, "job": 7554, "event": "table_file_deletion", "file_number": 87436}
2018-09-02 21:00:49.711469 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711465, "job": 7554, "event": "table_file_deletion", "file_number": 87435}
2018-09-02 21:00:49.711491 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711489, "job": 7554, "event": "table_file_deletion", "file_number": 87434}
2018-09-02 21:00:49.711513 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711509, "job": 7554, "event": "table_file_deletion", "file_number": 87433}
2018-09-02 21:00:49.711531 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711526, "job": 7554, "event": "table_file_deletion", "file_number": 87432}
2018-09-02 21:00:49.711563 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711562, "job": 7554, "event": "table_file_deletion", "file_number": 87431}
2018-09-02 21:00:49.711599 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711595, "job": 7554, "event": "table_file_deletion", "file_number": 87430}
2018-09-02 21:00:49.711624 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711619, "job": 7554, "event": "table_file_deletion", "file_number": 87429}
2018-09-02 21:00:49.711643 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711642, "job": 7554, "event": "table_file_deletion", "file_number": 87428}
2018-09-02 21:00:49.711657 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711655, "job": 7554, "event": "table_file_deletion", "file_number": 87427}
2018-09-02 21:00:49.711682 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711680, "job": 7554, "event": "table_file_deletion", "file_number": 87426}
2018-09-02 21:00:49.711700 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711696, "job": 7554, "event": "table_file_deletion", "file_number": 87425}
2018-09-02 21:00:49.711728 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711726, "job": 7554, "event": "table_file_deletion", "file_number": 87424}
2018-09-02 21:00:49.711753 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711751, "job": 7554, "event": "table_file_deletion", "file_number": 87423}
2018-09-02 21:00:49.711786 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711782, "job": 7554, "event": "table_file_deletion", "file_number": 87422}
2018-09-02 21:00:49.711808 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711804, "job": 7554, "event": "table_file_deletion", "file_number": 87421}
2018-09-02 21:00:49.711848 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711844, "job": 7554, "event": "table_file_deletion", "file_number": 86669}
2018-09-02 21:00:49.711926 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1403] [default] [JOB 7555] Compacting 1@2 + 6@3 files to L3, score 1.01
2018-09-02 21:00:49.711943 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1407] [default] Compaction start summary: Base version 7554 Base level 2, inputs: [87478(67MB)], [87379(66MB) 87380(65MB) 87381(65MB) 87382(1924KB) 86893(679KB) 86772(65MB)]
2018-09-02 21:00:49.711960 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914849711947, "job": 7555, "event": "compaction_started", "files_L2": [87478], "files_L3": [87379, 87380, 87381, 87382, 86893, 86772], "score": 1.00819, "input_data_size": 349546392}
2018-09-02 21:00:55.294902 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7555] Generated table #87499: 456999 keys, 69458262 bytes
2018-09-02 21:00:55.294944 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914855294918, "cf_name": "default", "job": 7555, "event": "table_file_creation", "file_number": 87499, "file_size": 69458262, "table_properties": {"data_size": 67111241, "index_size": 1053448, "filter_size": 1292586, "raw_key_size": 27859977, "raw_average_key_size": 60, "raw_value_size": 55378330, "raw_average_value_size": 121, "num_data_blocks": 16400, "num_entries": 456999, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:01:01.129812 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7555] Generated table #87500: 293634 keys, 69175134 bytes
2018-09-02 21:01:01.129852 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914861129832, "cf_name": "default", "job": 7555, "event": "table_file_creation", "file_number": 87500, "file_size": 69175134, "table_properties": {"data_size": 67112258, "index_size": 1177196, "filter_size": 884694, "raw_key_size": 17170058, "raw_average_key_size": 58, "raw_value_size": 60974083, "raw_average_value_size": 207, "num_data_blocks": 16103, "num_entries": 293634, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:01:06.129274 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7555] Generated table #87501: 111573 keys, 68787715 bytes
2018-09-02 21:01:06.129315 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914866129294, "cf_name": "default", "job": 7555, "event": "table_file_creation", "file_number": 87501, "file_size": 68787715, "table_properties": {"data_size": 67111996, "index_size": 1244245, "filter_size": 430488, "raw_key_size": 9721017, "raw_average_key_size": 87, "raw_value_size": 63144848, "raw_average_value_size": 565, "num_data_blocks": 14559, "num_entries": 111573, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:01:10.566639 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7555] Generated table #87502: 115647 keys, 68816267 bytes
2018-09-02 21:01:10.566677 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914870566659, "cf_name": "default", "job": 7555, "event": "table_file_creation", "file_number": 87502, "file_size": 68816267, "table_properties": {"data_size": 67112764, "index_size": 1261368, "filter_size": 441149, "raw_key_size": 10078038, "raw_average_key_size": 87, "raw_value_size": 63039652, "raw_average_value_size": 545, "num_data_blocks": 14622, "num_entries": 115647, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:01:11.340883 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1116] [default] [JOB 7555] Generated table #87503: 10556 keys, 7067798 bytes
2018-09-02 21:01:11.340920 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871340903, "cf_name": "default", "job": 7555, "event": "table_file_creation", "file_number": 87503, "file_size": 7067798, "table_properties": {"data_size": 6898533, "index_size": 126374, "filter_size": 41907, "raw_key_size": 919043, "raw_average_key_size": 87, "raw_value_size": 6508708, "raw_average_value_size": 616, "num_data_blocks": 1511, "num_entries": 10556, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "0", "kMergeOperands": "0"}}
2018-09-02 21:01:11.341016 7fef5521a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:1173] [default] [JOB 7555] Compacted 1@2 + 6@3 files to L3 => 283305176 bytes
2018-09-02 21:01:11.344124 7fef5521a700 4 rocksdb: (Original Log Time 2018/09/02-21:01:11.342113) [/build/ceph-12.2.5/src/rocksdb/db/compaction_job.cc:621] [default] compacted to: base level 1 max bytes base 268435456 files[0 4 38 64 0 0 0] max score 0.94, MB/sec: 16.2 rd, 13.1 wr, level 3, files in(1, 6) out(5) MB in(67.3, 266.0) out(270.2), read-write-amplify(9.0) write-amplify(4.0) OK, records in: 1917926, records dropped: 929499
2018-09-02 21:01:11.344140 7fef5521a700 4 rocksdb: (Original Log Time 2018/09/02-21:01:11.342149) EVENT_LOG_v1 {"time_micros": 1535914871342130, "job": 7555, "event": "compaction_finished", "compaction_time_micros": 21628988, "output_level": 3, "num_output_files": 5, "total_output_size": 283305176, "num_input_records": 1917908, "num_output_records": 988409, "num_subcompactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 4, 38, 64, 0, 0, 0]}
2018-09-02 21:01:11.344254 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344247, "job": 7555, "event": "table_file_deletion", "file_number": 87478}
2018-09-02 21:01:11.344300 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344296, "job": 7555, "event": "table_file_deletion", "file_number": 87382}
2018-09-02 21:01:11.344322 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344319, "job": 7555, "event": "table_file_deletion", "file_number": 87381}
2018-09-02 21:01:11.344347 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344343, "job": 7555, "event": "table_file_deletion", "file_number": 87380}
2018-09-02 21:01:11.344360 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344358, "job": 7555, "event": "table_file_deletion", "file_number": 87379}
2018-09-02 21:01:11.344387 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344383, "job": 7555, "event": "table_file_deletion", "file_number": 86893}
2018-09-02 21:01:11.344429 7fef5521a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535914871344424, "job": 7555, "event": "table_file_deletion", "file_number": 86772}
2018-09-02 21:03:51.615248 7fef5d22a700 -1 osd.35 pg_epoch: 62934 pg[34.24a( v 62934'594740 (62934'593216,62934'594740] local-lis/les=52161/52162 n=9219 ec=42458/9928 lis/c 52161/52161 les/c/f 52162/52162/20475 52161/52161/52133) [35,69,72] r=0 lpr=52161 crt=62934'594740 lcod 62934'594739 mlcod 62934'594739 active+clean+scrubbing+deep] _scan_snaps no head for 34:527410be:::rbd_data.216e8874b0dc51.000000000006ddb3:10a (have MIN)
2018-09-02 21:03:51.615284 7fef5d22a700 -1 osd.35 pg_epoch: 62934 pg[34.24a( v 62934'594740 (62934'593216,62934'594740] local-lis/les=52161/52162 n=9219 ec=42458/9928 lis/c 52161/52161 les/c/f 52162/52162/20475 52161/52161/52133) [35,69,72] r=0 lpr=52161 crt=62934'594740 lcod 62934'594739 mlcod 62934'594739 active+clean+scrubbing+deep] _scan_snaps no head for 34:527410be:::rbd_data.216e8874b0dc51.000000000006ddb3:102 (have MIN)
2018-09-02 21:04:03.412540 7fef6523a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_write.cc:684] reusing log 87469 from recycle list
2018-09-02 21:04:03.412729 7fef6523a700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_write.cc:725] [default] New memtable created with log file: #87504. Immutable memtables: 0.
2018-09-02 21:04:03.413402 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-21:04:03.412843) [/build/ceph-12.2.5/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
2018-09-02 21:04:03.413422 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:264] [default] [JOB 7556] Flushing memtable with next log file: 87504
2018-09-02 21:04:03.413451 7fef55a1b700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535915043413439, "job": 7556, "event": "flush_started", "num_memtables": 1, "num_entries": 128155, "num_deletes": 33427, "memory_usage": 260055392}
2018-09-02 21:04:03.413457 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:293] [default] [JOB 7556] Level-0 flush table #87505: started
2018-09-02 21:04:03.654126 7fef55a1b700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1535915043654105, "cf_name": "default", "job": 7556, "event": "table_file_creation", "file_number": 87505, "file_size": 13071683, "table_properties": {"data_size": 12789093, "index_size": 115313, "filter_size": 166288, "raw_key_size": 3002260, "raw_average_key_size": 54, "raw_value_size": 11800218, "raw_average_value_size": 213, "num_data_blocks": 1636, "num_entries": 55345, "filter_policy_name": "rocksdb.BuiltinBloomFilter", "kDeletedKeys": "26870", "kMergeOperands": "167"}}
2018-09-02 21:04:03.654148 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/flush_job.cc:319] [default] [JOB 7556] Level-0 flush table #87505: 13071683 bytes OK
2018-09-02 21:04:03.655577 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:242] adding log 87471 to recycle list
2018-09-02 21:04:03.655598 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-21:04:03.654161) [/build/ceph-12.2.5/src/rocksdb/db/memtable_list.cc:360] [default] Level-0 commit table #87505 started
2018-09-02 21:04:03.655605 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-21:04:03.655480) [/build/ceph-12.2.5/src/rocksdb/db/memtable_list.cc:383] [default] Level-0 commit table #87505: memtable #1 done
2018-09-02 21:04:03.655610 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-21:04:03.655505) EVENT_LOG_v1 {"time_micros": 1535915043655497, "job": 7556, "event": "flush_finished", "lsm_state": [1, 4, 38, 64, 0, 0, 0], "immutable_memtables": 0}
2018-09-02 21:04:03.655617 7fef55a1b700 4 rocksdb: (Original Log Time 2018/09/02-21:04:03.655558) [/build/ceph-12.2.5/src/rocksdb/db/db_impl_compaction_flush.cc:132] [default] Level summary: base level 1 max bytes base 268435456 files[1 4 38 64 0 0 0] max score 0.94
2018-09-02 21:04:03.655650 7fef55a1b700 4 rocksdb: [/build/ceph-12.2.5/src/rocksdb/db/db_impl_files.cc:388] [JOB 7556] Try to delete WAL files size 257284785, prev total WAL file size 257480816, number of live WAL files 2.
2018-09-02 21:05:51.772084 7fef5d22a700 0 log_channel(cluster) log [DBG] : 34.24a deep-scrub ok
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
