search

martinsumner / leveled

A pure Erlang Key/Value store - based on a LSM-tree, optimised for HEAD requests
Apache License 2.0
356 stars 33 forks source link

OTP 19 - Incredibly slow PUTs #112

Closed martinsumner closed 2 weeks ago

martinsumner commented 6 years ago

All testing so far has been focused on 18.3.

Running the rebar3 ct test for riak_SUITE handoff in 18.3 it reports:

40000 objects loaded in 6.330256 seconds

But in 19.3 it reports

40000 objects loaded in 429.411223 seconds

!!!!

martinsumner commented 6 years ago

This seems to be specific to the riak_sync strategy. If I run the same test with the 'sync' strategy I get in OTP19:

40000 objects loaded in 6.27153 second

The riak_sync strategy makes no sense in OTP 19, so perhaps strategy needs to be switched between sync/riak-sync in a smarter way.

benoitc commented 6 years ago

is using sync OK ?

martinsumner commented 6 years ago

Yes, it should be fine. riak_sync was only required in OTP16, as OTP16 didn't support the passing of the SYNC flag when opening a file handle. If you're not using OTP16 then you should use the sync flag if you want to make sure every PUT is flushed to disk before being ACK'd.

Obviously, using none and not flushing every write to disk is faster - this leaves the OS to decide when to flush. We still get good performance with sync in performance tests, but our test environments either have SSDs, or they have RAID controllers with FBWC (so the flush is actually to a bit of DRAM with a battery and a flash drive attached).

dergraf commented 5 years ago

Can confirm low write performance on 20.3 with 40k random writes in both none and sync sync strategy, using the leveled_bookie:book_put/5 API. No accurate measurements taken, but using none takes 2+ minutes, and using sync it takes 10+ minutes. Not sure what's going on, is there a miss-configuration? How to get better performance?

Keys are ~30 bytes and values are ~200 bytes small.

I start the book using the following options:

[
                {root_path, DbPath},
                {snapshot_bookie, undefined},
                {cache_size, 2500},
                {max_journalsize, 1000000000},
                {sync_strategy, sync},
                {head_only, false}, %% has to be false, otherwise only head request api
                {waste_retention_period, undefined},
                {max_run_length, undefined},
                {singlefile_compactionpercentage, 50.0},
                {maxrunlength_compactionpercentage, 70.0},
                {reload_strategy, []},
                {max_pencillercachesize, 400},
                {compression_method, lz4},
                {compression_point, on_receipt}
]

In case it's relevant (I don't see a major performance difference), instead of 40k sequential writes I run 40k sequences of undefinend == read(key), ok = write(key, value), value == read(key, value). But as said the performance doesn't really differs if I omit the surrounding read checks.

The logs for none sync strategy look like:

2018-11-24T10:41:39.843 CDB01 <0.6427.0> Opening file for writing with filename /home/graf/Projects/vernemq/_build/swc+test/logs/ct_run.nonode@nohost.2018-11-24_10.41.38/runner@marvin3d/basic/journal/journal_files/1_d20fbf8d-e7c8-4b10-9dc1-f024f3819a88.pnd
2018-11-24T10:41:39.844 CDB09 <0.6427.0> Failure to read Key/Value at Position 2048 in scan
2018-11-24T10:41:39.844 CDB06 <0.6427.0> File to be truncated at last position of 2048 with end of file at 0
2018-11-24T10:41:39.844 CDB13 <0.6427.0> Write options of [binary,raw,read,write]
2018-11-24T10:41:39.844 I0009 <0.6425.0> Updated manifest on startup:
2018-11-24T10:41:39.844 I0017 <0.6425.0> At SQN=1 journal has filename /home/graf/Projects/vernemq/_build/swc+test/logs/ct_run.nonode@nohost.2018-11-24_10.41.38/runner@marvin3d/basic/journal/journal_files/1_d20fbf8d-e7c8-4b10-9dc1-f024f3819a88
2018-11-24T10:41:39.845 I0016 <0.6425.0> Writing new version of manifest for manifestSQN=2
2018-11-24T10:41:39.864 PC001 <0.6428.0> Penciller's clerk <0.6429.0> started with owner <0.6428.0>
2018-11-24T10:41:39.872 P0013 <0.6428.0> Seqence number of 0 indicates no valid manifest
2018-11-24T10:41:39.872 P0014 <0.6428.0> Maximum sequence number of 0 found in nonzero levels
2018-11-24T10:41:39.872 P0035 <0.6428.0> Startup with Manifest SQN of 0
2018-11-24T10:41:39.872 P0017 <0.6428.0> No L0 file found
2018-11-24T10:41:39.872 B0005 <0.6424.0> LedgerSQN=0 at startup
2018-11-24T10:41:39.872 I0014 <0.6425.0> On startup loading from filename /home/graf/Projects/vernemq/_build/swc+test/logs/ct_run.nonode@nohost.2018-11-24_10.41.38/runner@marvin3d/basic/journal/journal_files/1_d20fbf8d-e7c8-4b10-9dc1-f024f3819a88 from SQN 1
2018-11-24T10:41:39.872 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:39.873 P0031 <0.6428.0> Completion of update to levelzero with cache size status false false with time taken 239 microsec
2018-11-24T10:41:39.873 B0001 <0.6424.0> Bookie starting with Ink <0.6425.0> Pcl <0.6428.0>
2018-11-24T10:41:39.916 I0002 <0.6425.0> Journal snapshot <0.6436.0> registered at SQN 2
2018-11-24T10:41:39.916 I0003 <0.6425.0> Journal snapshot <0.6436.0> released
2018-11-24T10:41:39.916 I0004 <0.6425.0> Remaining number of journal snapshots is 0
2018-11-24T10:41:39.961 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=958 body_time=4625 with fetch_count=61
2018-11-24T10:41:39.970 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=1055 ink_time=10596 with total_object_size=5441
2018-11-24T10:41:39.986 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=262 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:41:40.942 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:40.944 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 497 microsec
2018-11-24T10:41:41.286 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=633 body_time=3471 with fetch_count=63
2018-11-24T10:41:41.930 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:41.932 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 590 microsec
2018-11-24T10:41:42.268 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=293 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:41:42.420 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=732 ink_time=4160 with total_object_size=5700
2018-11-24T10:41:42.859 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=633 body_time=3282 with fetch_count=62
2018-11-24T10:41:42.946 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:42.948 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 506 microsec
2018-11-24T10:41:43.110 B0013 <0.6424.0> Long running task took 161191 microseconds with task of type pcl_head
2018-11-24T10:41:43.516 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=754 ink_time=4619 with total_object_size=5700
2018-11-24T10:41:44.074 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:44.077 P0019 <0.6428.0> Rolling level zero to filename ./1_0_0.sst at ledger sqn 26373
2018-11-24T10:41:44.085 P0031 <0.6428.0> Completion of update to levelzero with cache size status true true with time taken 8 ms
2018-11-24T10:41:44.312 B0013 <0.6424.0> Long running task took 235782 microseconds with task of type pcl_head
2018-11-24T10:41:44.549 B0013 <0.6424.0> Long running task took 235628 microseconds with task of type pcl_head
2018-11-24T10:41:44.552 PM002 <0.11716.0> Completed dump of L0 cache to list of size 10550 with time taken 467 ms
2018-11-24T10:41:44.603 SST03 <0.11716.0> Opening SST file with filename ./1_0_0.sst slots 83 and max sqn 26373
2018-11-24T10:41:44.603 SST08 <0.11716.0> Completed creation of ./1_0_0.sst at level 0 with max sqn 26373 with time taken 517 ms
2018-11-24T10:41:44.603 SST11 <0.11716.0> Level zero creation timings in microseconds pmem_fetch=467384 merge_lists=23437 build_slots=25127 build_summary=312 read_switch=1724
2018-11-24T10:41:44.603 P0029 <0.6428.0> L0 completion confirmed and will transition to not pending
2018-11-24T10:41:44.603 P0024 <0.6428.0> Outstanding compaction work items of 1 with backlog status of false
2018-11-24T10:41:44.603 PC008 <0.6429.0> Merge from level 0 to merge into 0 files below
2018-11-24T10:41:44.603 PC009 <0.6429.0> File ./1_0_0.sst to simply switch levels to level 1
2018-11-24T10:41:44.603 PC007 <0.6429.0> Clerk prompting Penciller regarding manifest change
2018-11-24T10:41:44.603 P0041 <0.6428.0> Penciller manifest switched from SQN 1 to 2
2018-11-24T10:41:44.603 PC017 <0.6429.0> Notified clerk of manifest change with time taken 6 microsec
2018-11-24T10:41:44.603 PC018 <0.6429.0> Saved manifest file with time taken 297 microsec
2018-11-24T10:41:44.603 PC022 <0.6429.0> Storing reference to deletions at ManifestSQN=2
2018-11-24T10:41:44.603 PC021 <0.6429.0> Prompting deletions at ManifestSQN=2
2018-11-24T10:41:44.633 SST12 <0.11716.0> SST Timings for sample_count=100 at timing points index_query_time=200 lookup_cache_time=48 slot_index_time=524  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:41:44.785 SST12 <0.11716.0> SST Timings for sample_count=100 at timing points index_query_time=188 lookup_cache_time=43 slot_index_time=501  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:41:45.005 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1004 body_time=3314 with fetch_count=62
2018-11-24T10:41:45.139 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1014 body_time=3529 with fetch_count=63
2018-11-24T10:41:45.576 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:45.579 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 563 microsec
2018-11-24T10:41:45.631 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=871 ink_time=5537 with total_object_size=5700
2018-11-24T10:41:46.633 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:46.636 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 671 microsec
2018-11-24T10:41:46.814 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=821 ink_time=4737 with total_object_size=5699
2018-11-24T10:41:47.068 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1367 body_time=3684 with fetch_count=62
2018-11-24T10:41:47.190 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=762 ink_time=4290 with total_object_size=5700
2018-11-24T10:41:47.735 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=1506 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:41:47.744 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:47.746 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 612 microsec
2018-11-24T10:41:47.848 B0013 <0.6424.0> Long running task took 101548 microseconds with task of type pcl_head
2018-11-24T10:41:48.828 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1066 body_time=3400 with fetch_count=62
2018-11-24T10:41:48.832 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:48.834 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 575 microsec
2018-11-24T10:41:49.041 B0013 <0.6424.0> Long running task took 205928 microseconds with task of type pcl_head
2018-11-24T10:41:49.248 B0013 <0.6424.0> Long running task took 206981 microseconds with task of type pcl_head
2018-11-24T10:41:49.607 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=717 ink_time=4099 with total_object_size=5700
2018-11-24T10:41:49.883 SST12 <0.11716.0> SST Timings for sample_count=100 at timing points index_query_time=157 lookup_cache_time=35 slot_index_time=473  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:41:50.258 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:50.261 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 1 ms
2018-11-24T10:41:50.683 B0013 <0.6424.0> Long running task took 421547 microseconds with task of type pcl_head
2018-11-24T10:41:50.994 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1103 body_time=3511 with fetch_count=63
2018-11-24T10:41:51.238 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=725 ink_time=4046 with total_object_size=5700
2018-11-24T10:41:51.435 SST12 <0.11716.0> SST Timings for sample_count=100 at timing points index_query_time=186 lookup_cache_time=38 slot_index_time=523  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:41:51.753 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:51.754 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 536 microsec
2018-11-24T10:41:55.365 B0013 <0.6424.0> Long running task took 3609782 microseconds with task of type pcl_head
2018-11-24T10:41:55.975 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=1462 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:41:56.251 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1102 body_time=3422 with fetch_count=63
2018-11-24T10:41:56.410 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:41:56.411 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 522 microsec
2018-11-24T10:42:02.175 B0013 <0.6424.0> Long running task took 5763792 microseconds with task of type pcl_head
2018-11-24T10:42:07.947 B0013 <0.6424.0> Long running task took 5771458 microseconds with task of type pcl_head
2018-11-24T10:42:08.111 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=790 ink_time=4688 with total_object_size=5700
2018-11-24T10:42:08.792 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=800 ink_time=4636 with total_object_size=5700
2018-11-24T10:42:09.070 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:42:09.071 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 576 microsec
2018-11-24T10:42:19.682 B0013 <0.6424.0> Long running task took 10610306 microseconds with task of type pcl_head
2018-11-24T10:42:20.167 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1556 body_time=5444 with fetch_count=62
2018-11-24T10:42:20.932 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:42:20.934 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 760 microsec
2018-11-24T10:42:32.307 B0013 <0.6424.0> Long running task took 11373322 microseconds with task of type pcl_head
2018-11-24T10:42:44.102 B0013 <0.6424.0> Long running task took 11794370 microseconds with task of type pcl_head
2018-11-24T10:42:44.464 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1265 body_time=4169 with fetch_count=63
2018-11-24T10:42:44.720 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=1868 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:42:44.774 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=1734 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:42:44.876 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=739 ink_time=4106 with total_object_size=5700
2018-11-24T10:42:45.276 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:42:45.277 P0019 <0.6428.0> Rolling level zero to filename ./3_0_0.sst at ledger sqn 92316
2018-11-24T10:42:45.278 P0031 <0.6428.0> Completion of update to levelzero with cache size status true true with time taken 754 microsec
2018-11-24T10:42:58.272 B0013 <0.6424.0> Long running task took 12992839 microseconds with task of type pcl_head
2018-11-24T10:42:58.309 PM002 <0.24915.0> Completed dump of L0 cache to list of size 26379 with time taken 13031 ms
2018-11-24T10:42:58.499 SST03 <0.24915.0> Opening SST file with filename ./3_0_0.sst slots 207 and max sqn 92316
2018-11-24T10:42:58.499 SST08 <0.24915.0> Completed creation of ./3_0_0.sst at level 0 with max sqn 92316 with time taken 13221 ms
2018-11-24T10:42:58.499 SST11 <0.24915.0> Level zero creation timings in microseconds pmem_fetch=13032036 merge_lists=126952 build_slots=58729 build_summary=597 read_switch=3112
2018-11-24T10:42:58.499 P0029 <0.6428.0> L0 completion confirmed and will transition to not pending
2018-11-24T10:42:58.500 P0024 <0.6428.0> Outstanding compaction work items of 1 with backlog status of false
2018-11-24T10:42:58.500 PC008 <0.6429.0> Merge from level 0 to merge into 1 files below
2018-11-24T10:42:58.500 PC010 <0.6429.0> Merge to be commenced for FileToMerge=./3_0_0.sst with MSN=4
2018-11-24T10:42:58.500 PC012 <0.6429.0> File to be created as part of MSN=4 Filename=./4_1_0.sst IsBasement=true
2018-11-24T10:42:58.585 SST13 <0.6429.0> SST merge list build timings of fold_toslot=49177 slot_hashlist=15191 slot_serialise=17085 slot_finish=2564 is_basement=true level=1
2018-11-24T10:42:58.587 SST12 <0.11716.0> SST Timings for sample_count=100 at timing points index_query_time=246 lookup_cache_time=43 slot_index_time=603  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:42:58.635 SST03 <0.25074.0> Opening SST file with filename ./4_1_0.sst slots 256 and max sqn 92316
2018-11-24T10:42:58.635 SST08 <0.25074.0> Completed creation of ./4_1_0.sst at level 1 with max sqn 92316 with time taken 46 ms
2018-11-24T10:42:58.635 PC015 <0.6429.0> File created with time taken 134 ms
2018-11-24T10:42:58.635 PC012 <0.6429.0> File to be created as part of MSN=4 Filename=./4_1_1.sst IsBasement=true
2018-11-24T10:42:58.644 SST13 <0.6429.0> SST merge list build timings of fold_toslot=4932 slot_hashlist=1517 slot_serialise=2195 slot_finish=594 is_basement=true level=1
2018-11-24T10:42:58.647 SST03 <0.25104.0> Opening SST file with filename ./4_1_1.sst slots 33 and max sqn 92316
2018-11-24T10:42:58.647 SST08 <0.25104.0> Completed creation of ./4_1_1.sst at level 1 with max sqn 92316 with time taken 2 ms
2018-11-24T10:42:58.647 PC015 <0.6429.0> File created with time taken 12 ms
2018-11-24T10:42:58.647 PC011 <0.6429.0> Merge completed with MSN=4 to Level=1 and FileCounter=2
2018-11-24T10:42:58.648 PC007 <0.6429.0> Clerk prompting Penciller regarding manifest change
2018-11-24T10:42:58.648 PC017 <0.6429.0> Notified clerk of manifest change with time taken 9 microsec
2018-11-24T10:42:58.648 P0041 <0.6428.0> Penciller manifest switched from SQN 3 to 4
2018-11-24T10:42:58.648 PC018 <0.6429.0> Saved manifest file with time taken 263 microsec
2018-11-24T10:42:58.648 PC022 <0.6429.0> Storing reference to deletions at ManifestSQN=4
2018-11-24T10:42:58.648 PC021 <0.6429.0> Prompting deletions at ManifestSQN=4
2018-11-24T10:42:58.846 SST12 <0.25074.0> SST Timings for sample_count=100 at timing points index_query_time=201 lookup_cache_time=48 slot_index_time=512  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:42:58.964 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=683 ink_time=4360 with total_object_size=5700
2018-11-24T10:42:59.412 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=740 body_time=3728 with fetch_count=62
2018-11-24T10:42:59.560 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:42:59.562 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 721 microsec
2018-11-24T10:43:00.722 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:00.724 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 829 microsec
2018-11-24T10:43:00.962 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1068 body_time=4553 with fetch_count=62
2018-11-24T10:43:02.000 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:02.002 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 776 microsec
2018-11-24T10:43:02.091 B0013 <0.6424.0> Long running task took 88272 microseconds with task of type pcl_head
2018-11-24T10:43:02.366 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=817 body_time=4331 with fetch_count=62
2018-11-24T10:43:02.543 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=820 ink_time=4935 with total_object_size=5700
2018-11-24T10:43:02.728 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=860 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:03.124 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=766 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:03.246 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:03.249 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 834 microsec
2018-11-24T10:43:03.556 B0013 <0.6424.0> Long running task took 307307 microseconds with task of type pcl_head
2018-11-24T10:43:03.756 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=783 ink_time=4708 with total_object_size=5700
2018-11-24T10:43:03.997 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=1102 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:04.138 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1007 body_time=4704 with fetch_count=63
2018-11-24T10:43:04.841 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:04.844 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 704 microsec
2018-11-24T10:43:06.559 B0013 <0.6424.0> Long running task took 1715638 microseconds with task of type pcl_head
2018-11-24T10:43:08.430 B0013 <0.6424.0> Long running task took 1870240 microseconds with task of type pcl_head
2018-11-24T10:43:08.638 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=701 ink_time=4329 with total_object_size=5700
2018-11-24T10:43:08.649 P0005 <0.6428.0> Delete confirmed as file ./3_0_0.sst is removed from Manifest
2018-11-24T10:43:08.649 P0005 <0.6428.0> Delete confirmed as file ./1_0_0.sst is removed from Manifest
2018-11-24T10:43:08.649 SST07 <0.24915.0> Exit called and now clearing ./3_0_0.sst
2018-11-24T10:43:08.649 SST07 <0.11716.0> Exit called and now clearing ./1_0_0.sst
2018-11-24T10:43:08.680 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=880 ink_time=5488 with total_object_size=5700
2018-11-24T10:43:09.541 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=858 body_time=3866 with fetch_count=63
2018-11-24T10:43:09.558 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:09.559 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 734 microsec
2018-11-24T10:43:13.363 B0013 <0.6424.0> Long running task took 3803471 microseconds with task of type pcl_head
2018-11-24T10:43:13.421 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=1014 ink_time=6220 with total_object_size=5700
2018-11-24T10:43:13.455 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1096 body_time=5058 with fetch_count=63
2018-11-24T10:43:13.778 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=863 body_time=3940 with fetch_count=63
2018-11-24T10:43:14.370 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=1010 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:14.498 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1123 body_time=4813 with fetch_count=62
2018-11-24T10:43:14.653 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:14.654 P0019 <0.6428.0> Rolling level zero to filename ./5_0_0.sst at ledger sqn 138687
2018-11-24T10:43:14.655 P0031 <0.6428.0> Completion of update to levelzero with cache size status true true with time taken 739 microsec
2018-11-24T10:43:20.659 B0013 <0.6424.0> Long running task took 6002125 microseconds with task of type pcl_head
2018-11-24T10:43:26.755 B0013 <0.6424.0> Long running task took 6088198 microseconds with task of type pcl_head
2018-11-24T10:43:26.762 PM002 <0.1431.1> Completed dump of L0 cache to list of size 18550 with time taken 12107 ms
2018-11-24T10:43:26.873 SST03 <0.1431.1> Opening SST file with filename ./5_0_0.sst slots 145 and max sqn 138687
2018-11-24T10:43:26.873 SST08 <0.1431.1> Completed creation of ./5_0_0.sst at level 0 with max sqn 138687 with time taken 12218 ms
2018-11-24T10:43:26.873 SST11 <0.1431.1> Level zero creation timings in microseconds pmem_fetch=12107400 merge_lists=67404 build_slots=40510 build_summary=623 read_switch=2790
2018-11-24T10:43:26.873 P0029 <0.6428.0> L0 completion confirmed and will transition to not pending
2018-11-24T10:43:26.874 P0024 <0.6428.0> Outstanding compaction work items of 1 with backlog status of false
2018-11-24T10:43:26.874 PC008 <0.6429.0> Merge from level 0 to merge into 2 files below
2018-11-24T10:43:26.874 PC010 <0.6429.0> Merge to be commenced for FileToMerge=./5_0_0.sst with MSN=6
2018-11-24T10:43:26.874 PC012 <0.6429.0> File to be created as part of MSN=6 Filename=./6_1_0.sst IsBasement=true
2018-11-24T10:43:26.957 SST13 <0.6429.0> SST merge list build timings of fold_toslot=42910 slot_hashlist=15020 slot_serialise=23703 slot_finish=856 is_basement=true level=1
2018-11-24T10:43:27.001 SST03 <0.1555.1> Opening SST file with filename ./6_1_0.sst slots 256 and max sqn 138687
2018-11-24T10:43:27.001 SST08 <0.1555.1> Completed creation of ./6_1_0.sst at level 1 with max sqn 138687 with time taken 42 ms
2018-11-24T10:43:27.001 PC015 <0.6429.0> File created with time taken 127 ms
2018-11-24T10:43:27.001 PC012 <0.6429.0> File to be created as part of MSN=6 Filename=./6_1_1.sst IsBasement=true
2018-11-24T10:43:27.050 SST13 <0.6429.0> SST merge list build timings of fold_toslot=25023 slot_hashlist=6102 slot_serialise=16544 slot_finish=1076 is_basement=true level=1
2018-11-24T10:43:27.091 SST03 <0.1615.1> Opening SST file with filename ./6_1_1.sst slots 178 and max sqn 138687
2018-11-24T10:43:27.091 SST08 <0.1615.1> Completed creation of ./6_1_1.sst at level 1 with max sqn 138687 with time taken 39 ms
2018-11-24T10:43:27.091 PC015 <0.6429.0> File created with time taken 90 ms
2018-11-24T10:43:27.092 PC011 <0.6429.0> Merge completed with MSN=6 to Level=1 and FileCounter=2
2018-11-24T10:43:27.092 PC007 <0.6429.0> Clerk prompting Penciller regarding manifest change
2018-11-24T10:43:27.092 PC017 <0.6429.0> Notified clerk of manifest change with time taken 8 microsec
2018-11-24T10:43:27.092 P0041 <0.6428.0> Penciller manifest switched from SQN 5 to 6
2018-11-24T10:43:27.092 PC018 <0.6429.0> Saved manifest file with time taken 261 microsec
2018-11-24T10:43:27.092 PC022 <0.6429.0> Storing reference to deletions at ManifestSQN=6
2018-11-24T10:43:27.092 PC021 <0.6429.0> Prompting deletions at ManifestSQN=6
2018-11-24T10:43:27.290 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=829 ink_time=4894 with total_object_size=5700
2018-11-24T10:43:27.318 SST12 <0.1555.1> SST Timings for sample_count=100 at timing points index_query_time=209 lookup_cache_time=52 slot_index_time=565  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:43:27.502 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1037 body_time=4164 with fetch_count=63
2018-11-24T10:43:28.002 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:28.004 P0019 <0.6428.0> Rolling level zero to filename ./7_0_0.sst at ledger sqn 145211
2018-11-24T10:43:28.005 P0031 <0.6428.0> Completion of update to levelzero with cache size status true true with time taken 1 ms
2018-11-24T10:43:28.005 PM002 <0.2739.1> Completed dump of L0 cache to list of size 2612 with time taken 738 microsec
2018-11-24T10:43:28.010 SST03 <0.2739.1> Opening SST file with filename ./7_0_0.sst slots 21 and max sqn 145211
2018-11-24T10:43:28.010 SST08 <0.2739.1> Completed creation of ./7_0_0.sst at level 0 with max sqn 145211 with time taken 5 ms
2018-11-24T10:43:28.010 SST11 <0.2739.1> Level zero creation timings in microseconds pmem_fetch=790 merge_lists=2725 build_slots=1186 build_summary=104 read_switch=633
2018-11-24T10:43:28.022 P0029 <0.6428.0> L0 completion confirmed and will transition to not pending
2018-11-24T10:43:28.022 P0024 <0.6428.0> Outstanding compaction work items of 1 with backlog status of false
2018-11-24T10:43:28.022 PC008 <0.6429.0> Merge from level 0 to merge into 2 files below
2018-11-24T10:43:28.022 PC010 <0.6429.0> Merge to be commenced for FileToMerge=./7_0_0.sst with MSN=8
2018-11-24T10:43:28.022 PC012 <0.6429.0> File to be created as part of MSN=8 Filename=./8_1_0.sst IsBasement=true
2018-11-24T10:43:28.101 SST13 <0.6429.0> SST merge list build timings of fold_toslot=45280 slot_hashlist=11683 slot_serialise=19009 slot_finish=1880 is_basement=true level=1
2018-11-24T10:43:28.146 SST03 <0.2813.1> Opening SST file with filename ./8_1_0.sst slots 256 and max sqn 145211
2018-11-24T10:43:28.146 SST08 <0.2813.1> Completed creation of ./8_1_0.sst at level 1 with max sqn 145211 with time taken 42 ms
2018-11-24T10:43:28.146 PC015 <0.6429.0> File created with time taken 124 ms
2018-11-24T10:43:28.146 PC012 <0.6429.0> File to be created as part of MSN=8 Filename=./8_1_1.sst IsBasement=true
2018-11-24T10:43:28.221 SST13 <0.6429.0> SST merge list build timings of fold_toslot=38668 slot_hashlist=11948 slot_serialise=20389 slot_finish=2927 is_basement=true level=1
2018-11-24T10:43:28.291 SST03 <0.2875.1> Opening SST file with filename ./8_1_1.sst slots 198 and max sqn 145211
2018-11-24T10:43:28.291 SST08 <0.2875.1> Completed creation of ./8_1_1.sst at level 1 with max sqn 145211 with time taken 67 ms
2018-11-24T10:43:28.291 PC015 <0.6429.0> File created with time taken 144 ms
2018-11-24T10:43:28.291 PC011 <0.6429.0> Merge completed with MSN=8 to Level=1 and FileCounter=2
2018-11-24T10:43:28.291 PC007 <0.6429.0> Clerk prompting Penciller regarding manifest change
2018-11-24T10:43:28.291 PC017 <0.6429.0> Notified clerk of manifest change with time taken 12 microsec
2018-11-24T10:43:28.291 P0041 <0.6428.0> Penciller manifest switched from SQN 7 to 8
2018-11-24T10:43:28.292 PC018 <0.6429.0> Saved manifest file with time taken 280 microsec
2018-11-24T10:43:28.292 PC022 <0.6429.0> Storing reference to deletions at ManifestSQN=8
2018-11-24T10:43:28.292 PC021 <0.6429.0> Prompting deletions at ManifestSQN=8
2018-11-24T10:43:28.571 SST12 <0.2813.1> SST Timings for sample_count=100 at timing points index_query_time=326 lookup_cache_time=97 slot_index_time=706  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:43:28.836 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=847 body_time=3726 with fetch_count=63
2018-11-24T10:43:28.858 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1009 body_time=3905 with fetch_count=63
2018-11-24T10:43:29.344 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=788 ink_time=4808 with total_object_size=5700
2018-11-24T10:43:29.411 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:29.413 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 707 microsec
2018-11-24T10:43:30.325 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1379 body_time=4375 with fetch_count=63
2018-11-24T10:43:30.481 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:30.483 P0019 <0.6428.0> Rolling level zero to filename ./9_0_0.sst at ledger sqn 158247
2018-11-24T10:43:30.483 P0031 <0.6428.0> Completion of update to levelzero with cache size status true true with time taken 717 microsec
2018-11-24T10:43:30.493 PM002 <0.5352.1> Completed dump of L0 cache to list of size 5216 with time taken 9 ms
2018-11-24T10:43:30.516 SST03 <0.5352.1> Opening SST file with filename ./9_0_0.sst slots 41 and max sqn 158247
2018-11-24T10:43:30.516 SST08 <0.5352.1> Completed creation of ./9_0_0.sst at level 0 with max sqn 158247 with time taken 32 ms
2018-11-24T10:43:30.516 SST11 <0.5352.1> Level zero creation timings in microseconds pmem_fetch=15852 merge_lists=7331 build_slots=7729 build_summary=340 read_switch=1404
2018-11-24T10:43:30.612 B0013 <0.6424.0> Long running task took 127678 microseconds with task of type pcl_head
2018-11-24T10:43:30.612 P0029 <0.6428.0> L0 completion confirmed and will transition to not pending
2018-11-24T10:43:30.613 P0024 <0.6428.0> Outstanding compaction work items of 1 with backlog status of false
2018-11-24T10:43:30.613 PC008 <0.6429.0> Merge from level 0 to merge into 2 files below
2018-11-24T10:43:30.613 PC010 <0.6429.0> Merge to be commenced for FileToMerge=./9_0_0.sst with MSN=10
2018-11-24T10:43:30.613 PC012 <0.6429.0> File to be created as part of MSN=10 Filename=./10_1_0.sst IsBasement=true
2018-11-24T10:43:30.716 SST13 <0.6429.0> SST merge list build timings of fold_toslot=54395 slot_hashlist=14192 slot_serialise=31138 slot_finish=2295 is_basement=true level=1
2018-11-24T10:43:30.768 SST03 <0.5417.1> Opening SST file with filename ./10_1_0.sst slots 256 and max sqn 158247
2018-11-24T10:43:30.768 SST08 <0.5417.1> Completed creation of ./10_1_0.sst at level 1 with max sqn 158247 with time taken 47 ms
2018-11-24T10:43:30.768 PC015 <0.6429.0> File created with time taken 154 ms
2018-11-24T10:43:30.768 PC012 <0.6429.0> File to be created as part of MSN=10 Filename=./10_1_1.sst IsBasement=true
2018-11-24T10:43:30.835 SST13 <0.6429.0> SST merge list build timings of fold_toslot=34184 slot_hashlist=9278 slot_serialise=21429 slot_finish=1623 is_basement=true level=1
2018-11-24T10:43:30.921 SST03 <0.5489.1> Opening SST file with filename ./10_1_1.sst slots 239 and max sqn 158247
2018-11-24T10:43:30.921 SST08 <0.5489.1> Completed creation of ./10_1_1.sst at level 1 with max sqn 158247 with time taken 84 ms
2018-11-24T10:43:30.921 PC015 <0.6429.0> File created with time taken 153 ms
2018-11-24T10:43:30.922 PC011 <0.6429.0> Merge completed with MSN=10 to Level=1 and FileCounter=2
2018-11-24T10:43:30.922 PC007 <0.6429.0> Clerk prompting Penciller regarding manifest change
2018-11-24T10:43:30.922 PC017 <0.6429.0> Notified clerk of manifest change with time taken 11 microsec
2018-11-24T10:43:30.922 P0041 <0.6428.0> Penciller manifest switched from SQN 9 to 10
2018-11-24T10:43:30.922 PC018 <0.6429.0> Saved manifest file with time taken 250 microsec
2018-11-24T10:43:30.922 PC022 <0.6429.0> Storing reference to deletions at ManifestSQN=10
2018-11-24T10:43:30.922 PC021 <0.6429.0> Prompting deletions at ManifestSQN=10
2018-11-24T10:43:31.122 SST12 <0.5417.1> SST Timings for sample_count=100 at timing points index_query_time=248 lookup_cache_time=61 slot_index_time=574  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:43:31.289 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=939 ink_time=5990 with total_object_size=5700
2018-11-24T10:43:31.978 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:31.980 P0019 <0.6428.0> Rolling level zero to filename ./11_0_0.sst at ledger sqn 164895
2018-11-24T10:43:31.980 P0031 <0.6428.0> Completion of update to levelzero with cache size status true true with time taken 1 ms
2018-11-24T10:43:31.981 PM002 <0.6685.1> Completed dump of L0 cache to list of size 2661 with time taken 1 ms
2018-11-24T10:43:31.986 SST03 <0.6685.1> Opening SST file with filename ./11_0_0.sst slots 21 and max sqn 164895
2018-11-24T10:43:31.986 SST08 <0.6685.1> Completed creation of ./11_0_0.sst at level 0 with max sqn 164895 with time taken 5 ms
2018-11-24T10:43:31.986 SST11 <0.6685.1> Level zero creation timings in microseconds pmem_fetch=1075 merge_lists=3018 build_slots=1060 build_summary=102 read_switch=704
2018-11-24T10:43:31.993 P0029 <0.6428.0> L0 completion confirmed and will transition to not pending
2018-11-24T10:43:31.993 P0024 <0.6428.0> Outstanding compaction work items of 1 with backlog status of false
2018-11-24T10:43:31.993 PC008 <0.6429.0> Merge from level 0 to merge into 2 files below
2018-11-24T10:43:31.993 PC010 <0.6429.0> Merge to be commenced for FileToMerge=./11_0_0.sst with MSN=12
2018-11-24T10:43:31.994 PC012 <0.6429.0> File to be created as part of MSN=12 Filename=./12_1_0.sst IsBasement=true
2018-11-24T10:43:32.074 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=1178 body_time=5070 with fetch_count=62
2018-11-24T10:43:32.078 SST13 <0.6429.0> SST merge list build timings of fold_toslot=45580 slot_hashlist=14438 slot_serialise=20636 slot_finish=2640 is_basement=true level=1
2018-11-24T10:43:32.124 SST03 <0.6756.1> Opening SST file with filename ./12_1_0.sst slots 256 and max sqn 164895
2018-11-24T10:43:32.124 SST08 <0.6756.1> Completed creation of ./12_1_0.sst at level 1 with max sqn 164895 with time taken 42 ms
2018-11-24T10:43:32.124 PC015 <0.6429.0> File created with time taken 130 ms
2018-11-24T10:43:32.124 PC012 <0.6429.0> File to be created as part of MSN=12 Filename=./12_1_1.sst IsBasement=true
2018-11-24T10:43:32.194 SST13 <0.6429.0> SST merge list build timings of fold_toslot=37360 slot_hashlist=10785 slot_serialise=19351 slot_finish=1791 is_basement=true level=1
2018-11-24T10:43:32.236 SST03 <0.6838.1> Opening SST file with filename ./12_1_1.sst slots 256 and max sqn 164895
2018-11-24T10:43:32.236 SST08 <0.6838.1> Completed creation of ./12_1_1.sst at level 1 with max sqn 164895 with time taken 39 ms
2018-11-24T10:43:32.236 PC015 <0.6429.0> File created with time taken 111 ms
2018-11-24T10:43:32.236 PC012 <0.6429.0> File to be created as part of MSN=12 Filename=./12_1_2.sst IsBasement=true
2018-11-24T10:43:32.237 SST13 <0.6429.0> SST merge list build timings of fold_toslot=81 slot_hashlist=145 slot_serialise=272 slot_finish=16 is_basement=true level=1
2018-11-24T10:43:32.238 SST03 <0.6854.1> Opening SST file with filename ./12_1_2.sst slots 4 and max sqn 164895
2018-11-24T10:43:32.238 SST08 <0.6854.1> Completed creation of ./12_1_2.sst at level 1 with max sqn 164895 with time taken 724 microsec
2018-11-24T10:43:32.238 PC015 <0.6429.0> File created with time taken 1 ms
2018-11-24T10:43:32.238 PC011 <0.6429.0> Merge completed with MSN=12 to Level=1 and FileCounter=3
2018-11-24T10:43:32.238 PC007 <0.6429.0> Clerk prompting Penciller regarding manifest change
2018-11-24T10:43:32.238 P0041 <0.6428.0> Penciller manifest switched from SQN 11 to 12
2018-11-24T10:43:32.238 PC017 <0.6429.0> Notified clerk of manifest change with time taken 17 microsec
2018-11-24T10:43:32.239 PC018 <0.6429.0> Saved manifest file with time taken 438 microsec
2018-11-24T10:43:32.239 PC022 <0.6429.0> Storing reference to deletions at ManifestSQN=12
2018-11-24T10:43:32.239 PC021 <0.6429.0> Prompting deletions at ManifestSQN=12
2018-11-24T10:43:32.475 SST12 <0.6756.1> SST Timings for sample_count=100 at timing points index_query_time=186 lookup_cache_time=45 slot_index_time=483  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:43:32.774 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=822 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:33.023 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=840 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:33.060 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=796 ink_time=5058 with total_object_size=5699
2018-11-24T10:43:33.086 SST12 <0.6838.1> SST Timings for sample_count=100 at timing points index_query_time=194 lookup_cache_time=52 slot_index_time=513  fetch_cache_time=0 slot_fetch_time=0 noncached_block_fetch_time=0 exiting at points slot_index=100 fetch_cache=0 slot_fetch=0 noncached_block_fetch=0
2018-11-24T10:43:33.225 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:33.227 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 681 microsec
2018-11-24T10:43:33.990 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=840 body_time=3979 with fetch_count=62
2018-11-24T10:43:34.326 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:34.328 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 611 microsec
2018-11-24T10:43:35.542 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:35.544 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 597 microsec
2018-11-24T10:43:35.646 B0013 <0.6424.0> Long running task took 101127 microseconds with task of type pcl_head
2018-11-24T10:43:35.753 B0013 <0.6424.0> Long running task took 106728 microseconds with task of type pcl_head
2018-11-24T10:43:35.946 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=756 body_time=3875 with fetch_count=62
2018-11-24T10:43:36.356 B0015 <0.6424.0> Put timing with sample_count=100 and mem_time=862 ink_time=5222 with total_object_size=5700
2018-11-24T10:43:36.551 P0032 <0.6428.0> Fetch head timing with sample_count=100 and level timings of foundmem_time=0 found0_time=0 found1_time=0 found2_time=0 found3_time=0 foundlower_time=0 missed_time=934 with counts of foundmem_count=0 found0_count=0 found1_count=0 found2_count=0 found3_count=0 foundlower_count=0 missed_count=100
2018-11-24T10:43:36.974 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:36.976 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 829 microsec
2018-11-24T10:43:37.232 B0013 <0.6424.0> Long running task took 256427 microseconds with task of type pcl_head
2018-11-24T10:43:37.232 P0005 <0.6428.0> Delete confirmed as file ./5_0_0.sst is removed from Manifest
2018-11-24T10:43:37.233 P0005 <0.6428.0> Delete confirmed as file ./4_1_0.sst is removed from Manifest
2018-11-24T10:43:37.233 SST07 <0.1431.1> Exit called and now clearing ./5_0_0.sst
2018-11-24T10:43:37.233 P0005 <0.6428.0> Delete confirmed as file ./4_1_1.sst is removed from Manifest
2018-11-24T10:43:37.233 SST07 <0.25074.0> Exit called and now clearing ./4_1_0.sst
2018-11-24T10:43:37.233 SST07 <0.25104.0> Exit called and now clearing ./4_1_1.sst
2018-11-24T10:43:37.442 B0013 <0.6424.0> Long running task took 208717 microseconds with task of type pcl_head
2018-11-24T10:43:37.750 B0016 <0.6424.0> Get timing with sample_count=100 and head_time=927 body_time=4254 with fetch_count=63
2018-11-24T10:43:38.293 P0005 <0.6428.0> Delete confirmed as file ./7_0_0.sst is removed from Manifest
2018-11-24T10:43:38.293 P0005 <0.6428.0> Delete confirmed as file ./6_1_0.sst is removed from Manifest
2018-11-24T10:43:38.293 SST07 <0.2739.1> Exit called and now clearing ./7_0_0.sst
2018-11-24T10:43:38.293 P0005 <0.6428.0> Delete confirmed as file ./6_1_1.sst is removed from Manifest
2018-11-24T10:43:38.293 SST07 <0.1555.1> Exit called and now clearing ./6_1_0.sst
2018-11-24T10:43:38.293 SST07 <0.1615.1> Exit called and now clearing ./6_1_1.sst
2018-11-24T10:43:38.685 P0018 <0.6428.0> Response to push_mem of ok with L0 pending false and merge backlog false
2018-11-24T10:43:38.688 P0031 <0.6428.0> Completion of update to levelzero with cache size status true false with time taken 814 microsec
2018-11-24T10:43:40.993 P0005 <0.6428.0> Delete confirmed as file ./9_0_0.sst is removed from Manifest
2018-11-24T10:43:40.993 B0013 <0.6424.0> Long running task took 2305064 microseconds with task of type pcl_head
2018-11-24T10:43:40.993 P0005 <0.6428.0> Delete confirmed as file ./8_1_0.sst is removed from Manifest
2018-11-24T10:43:40.993 SST07 <0.5352.1> Exit called and now clearing ./9_0_0.sst
2018-11-24T10:43:40.993 P0005 <0.6428.0> Delete confirmed as file ./8_1_1.sst is removed from Manifest
2018-11-24T10:43:40.993 SST07 <0.2813.1> Exit called and now clearing ./8_1_0.sst
2018-11-24T10:43:40.993 SST07 <0.2875.1> Exit called and now clearing ./8_1_1.sst
2018-11-24T10:43:41.327 I0002 <0.6425.0> Journal snapshot <0.13711.1> registered at SQN 2
2018-11-24T10:43:42.027 I0003 <0.6425.0> Journal snapshot <0.13711.1> released
2018-11-24T10:43:42.028 I0004 <0.6425.0> Remaining number of journal snapshots is 0
2018-11-24T10:43:42.036 I0002 <0.6425.0> Journal snapshot <0.13713.1> registered at SQN 2
2018-11-24T10:43:42.240 P0005 <0.6428.0> Delete confirmed as file ./11_0_0.sst is removed from Manifest
2018-11-24T10:43:42.240 P0005 <0.6428.0> Delete confirmed as file ./10_1_0.sst is removed from Manifest
2018-11-24T10:43:42.240 SST07 <0.6685.1> Exit called and now clearing ./11_0_0.sst
2018-11-24T10:43:42.240 SST07 <0.5417.1> Exit called and now clearing ./10_1_0.sst
2018-11-24T10:43:42.240 P0005 <0.6428.0> Delete confirmed as file ./10_1_1.sst is removed from Manifest
2018-11-24T10:43:42.240 SST07 <0.5489.1> Exit called and now clearing ./10_1_1.sst
2018-11-24T10:43:42.749 I0003 <0.6425.0> Journal snapshot <0.13713.1> released
2018-11-24T10:43:42.750 I0004 <0.6425.0> Remaining number of journal snapshots is 0
2018-11-24T10:43:42.756 I0002 <0.6425.0> Journal snapshot <0.13715.1> registered at SQN 2
2018-11-24T10:43:43.501 I0003 <0.6425.0> Journal snapshot <0.13715.1> released
2018-11-24T10:43:43.501 I0004 <0.6425.0> Remaining number of journal snapshots is 0
2018-11-24T10:43:43.509 I0002 <0.6425.0> Journal snapshot <0.13717.1> registered at SQN 2
2018-11-24T10:43:44.156 I0003 <0.6425.0> Journal snapshot <0.13717.1> released
2018-11-24T10:43:44.156 I0004 <0.6425.0> Remaining number of journal snapshots is 0
2018-11-24T10:43:44.169 I0005 <0.6425.0> Inker closing journal for reason close
2018-11-24T10:43:44.169 I0006 <0.6425.0> Close triggered with journal_sqn=200003 and manifest_sqn=2
2018-11-24T10:43:44.169 I0007 <0.6425.0> Inker manifest when closing is:
2018-11-24T10:43:44.169 I0017 <0.6425.0> At SQN=1 journal has filename /home/graf/Projects/vernemq/_build/swc+test/logs/ct_run.nonode@nohost.2018-11-24_10.41.38/runner@marvin3d/basic/journal/journal_files/1_d20fbf8d-e7c8-4b10-9dc1-f024f3819a88
2018-11-24T10:43:44.169 CDB05 <0.6427.0> Closing of filename /home/graf/Projects/vernemq/_build/swc+test/logs/ct_run.nonode@nohost.2018-11-24_10.41.38/runner@marvin3d/basic/journal/journal_files/1_d20fbf8d-e7c8-4b10-9dc1-f024f3819a88.pnd from state writer for reason cdb_close
2018-11-24T10:43:44.172 PC005 <0.6429.0> Penciller's Clerk <0.6429.0> shutdown now complete for reason normal
2018-11-24T10:43:44.176 P0008 <0.6428.0> Penciller closing for reason close
2018-11-24T10:43:44.196 PM002 <0.6428.0> Completed dump of L0 cache to list of size 13301 with time taken 13 ms
2018-11-24T10:43:44.285 SST03 <0.13718.1> Opening SST file with filename ./13_0_0.sst slots 104 and max sqn 198141
2018-11-24T10:43:44.285 SST08 <0.13718.1> Completed creation of ./13_0_0.sst at level 0 with max sqn 198141 with time taken 27 ms
2018-11-24T10:43:44.285 SST04 <0.13718.1> Exit called for reason normal on filename ./13_0_0.sst
2018-11-24T10:43:44.285 SST04 <0.6756.1> Exit called for reason normal on filename ./12_1_0.sst
2018-11-24T10:43:44.286 SST04 <0.6838.1> Exit called for reason normal on filename ./12_1_1.sst
2018-11-24T10:43:44.286 SST04 <0.6854.1> Exit called for reason normal on filename ./12_1_2.sst
2018-11-24T10:43:44.286 P0011 <0.6428.0> Shutdown complete for Penciller for reason normal
2018-11-24T10:43:44.286 B0003 <0.6424.0> Bookie closing for reason normal
martinsumner commented 5 years ago

There's something not right there.

There's some timing points in the rebar3 ct tests that do similar loads.

if you do rebar3 ct --suite=test/end_to_end/basic_SUITE

The look in the logs of the tes and there will be log lines like this:

5000 objects loaded in 0.349584 seconds

Typically in these tests I'm seeing > 10K writes per second on my macbook.

martinsumner commented 5 years ago

One thing to note is that your max_penciller_cache_size is very, very small.

{max_pencillercachesize, 400}

Default for this is 28000. I wouldn't recommend playing with this. If you look in your logs you're getting occasional logs like this:

2018-11-24T10:43:20.659 B0013 <0.6424.0> Long running task took 6002125 microseconds with task of type pcl_head
2018-11-24T10:43:26.755 B0013 <0.6424.0> Long running task took 6088198 microseconds with task of type pcl_head

Which is very unusual, and may be related to your small max_penciller cache size. Every time the penciller cache is full, it needs to flush a L0 file to the top of the LSM tree, and it can't flush a file until the previous L0 file has been merged down. Having a small L0 files will generate write amplification. So generally the Penciller Cache size is aligned roughly with the size of an SST file (typically 32000 entries).

martinsumner commented 5 years ago

The only other setting that may be worth tuning is the max_journal_size. If you have small objects, it is recommended to use a smaller size.

Some more details - https://github.com/martinsumner/leveled/blob/master/docs/STARTUP_OPTIONS.md#max-journal-size

But I don't think your journal size is causing an issue in this test.

dergraf commented 5 years ago

Ok, the end_to_end/basic_SUITE took about 8minutes to complete (ok?), however I found the mentioned entries in the log, and indeed they show quite good numbers e.g. 20000 objects loaded in 1.167182 seconds.

The following simple test case took about 3 minutes to complete on my machine...

basic_store_direct_test(_Config) ->
    {ok, Bookie} =
    leveled_bookie:book_start([
                {root_path, "./bookie-test"},
                {snapshot_bookie, undefined},
                {cache_size, 2500},
                {max_journalsize, 100000000},
                {sync_strategy, sync},
                {head_only, false}, %% has to be false, otherwise only head request api
                {waste_retention_period, undefined},
                {max_run_length, undefined},
                {singlefile_compactionpercentage, 50.0},
                {maxrunlength_compactionpercentage, 70.0},
                {reload_strategy, []},
                {max_pencillercachesize, 28000},
                {compression_method, lz4},
                {compression_point, on_receipt}]),

    Prefixes = [{a,a},{a,b},{a,c},{a,d}],
    _KVPairsByPrefix =
    lists:foldl(
      fun(I, Acc) ->
              lists:foldl(
                fun(P, _AccAcc) ->
                        Key = sext:encode({P, I}),
                        Val = term_to_binary(I),
                        not_found = leveled_bookie:book_get(Bookie, <<"test">>, Key),
                        ok = leveled_bookie:book_put(Bookie, <<"test">>, Key, Val, []),
                        {ok, Val} = leveled_bookie:book_get(Bookie, <<"test">>, Key)
                end, Acc, Prefixes)
      end, #{}, lists:seq(1, 10000)).
dergraf commented 5 years ago

I have to investigate a bit more.. for whatever reasons the test above with sync strategy none performs way better than I have initially measured.

martinsumner commented 5 years ago

I will give your test a run this evening on a couple of machines to see what happens. Turning sync on normally requires either a SSD or a write-cache to get reasonable performance. But 3 minutes seems way, way too long even with a old-syle spinning disk.

dergraf commented 5 years ago

Figured out that my original test (storing the 40k objects) was actually doing around 80k put operations instead of the 40k. The reason for this is that every store insert (talking about our store that is backed by leveled) requires to store the actual object as well as it updates a single specific object inside a different bucket. So the sequence is rather like the following:

leveled_bookie:book_put(Bookie, <<"data">>, <<"key1">>, <<"val1">>, []).
leveled_bookie:book_put(Bookie, <<"other">>, <<"ctx">>, <<"updatedcontext">>, []).
leveled_bookie:book_put(Bookie, <<"data">>, <<"key2">>, <<"val2">>, []).
leveled_bookie:book_put(Bookie, <<"other">>, <<"ctx">>, <<"updatedcontext">>, []).
...
leveled_bookie:book_put(Bookie, <<"data">>, <<"key40000">>, <<"val40000">>, []).
leveled_bookie:book_put(Bookie, <<"other">>, <<"ctx">>, <<"updatedcontext">>, []).

Is it possible that "switching" buckets is causing the slow down? Moreover every put is preceded by one or two reads.

martinsumner commented 5 years ago

For basic_store_direct_test/1 on a macbook I get:

sync_strategy: sync - 8.291s sync_strategy: none - 6.153s

So very different to the 3 minutes you get.

I have a desktop with a fusion drive (so not pure SSD). This has timings of

sync_strategy: sync - 10.632s sync_strategy: none - 17.336s

If you look in the logs of the test run, on the fusion drive machine the log B0015 shows a much higher ink_time when compared to the pure SSD laptop test. The ink_time is where the write to disk (and the flush occurs when sync is enabled).

martinsumner commented 2 weeks ago

OTP19 no longer supported