diff --git a/docs/LATENCY.md b/docs/LATENCY.md index 212fea4..41b3486 100644 --- a/docs/LATENCY.md +++ b/docs/LATENCY.md @@ -30,7 +30,7 @@ The Put time measurement chart compares the time taken by the Inker to persist t ![](pics/23Nov_PutTimeSplit.png) -## Head Time +## Head Time - Penciller The time for Head requests is broken down in two ways: the time based on the level of the merge tree from which it was fetched; the timings within the SST file processes themselves. @@ -38,6 +38,8 @@ The time for Head requests is broken down in two ways: the time based on the lev The timings for the merge tree are surprisingly high for missing entries (which largely should be covered by bloom filter checks), and there is a surprisingly high gap between the timings for different levels (again given the expected speed of the bloom checks). +### Improvements + This has been improved, first by changing the bloom filter and passing the bloom so that it can be accessed directly without a message pass from the penciller: ![](pics/28Nov_HeadTimeSplit.png) @@ -46,6 +48,10 @@ A second improvement was to include a small (32) cache of recently fetched keys ![](pics/29Nov_HeadTimeSplit.png) +It should be noted that the combined overall throughput improvement from these changes is somewhere between 2% and 5%. So although the difference in the low-level measurements are significant (> 100 microseconds), and the volumes of HEAD requests is high (either 3 or 4 for each transaction) - the final difference is marginal. + +## Head Time - File Level + Within the SST file, the timings are broken down between index_query (the time taken to find the slot in the tree), tiny_bloom (the time taken to check against the bloom filter for that slot), slot_index (the time taken to look up the position in the slot - which may also double as a bloom filter to determine non_presence) and slot_fetch (the time taken to fetch the block from disk and perform binary_to_term and then walk to the position). ![](pics/23Nov_SSTFetchTimeSplit.png) @@ -63,3 +69,19 @@ This can also be broken down for each individual SST file request (note that mos 80% of file requests exit after the bloom check. Very few false positives are discovered after the bloom check in the slot_index check, so 20% of fetch requests to files result in a slot_fetch. ## Merge Time + +First metric of interest is the total time (per second) taken for files to be created during the merge process, as reported by the Penciller's Clerk: + +![](pics/PerHostTotalFileCreateTime.png) + +For Level Zero files there is a breakdown of where this time is spent: + +![](pics/Level0CreateTimeSplit.png) + +Note that the fetch_pmem process only exists for Level Zero files. Below Level Zero the files have a more complicated merge_lists process, but not fetch from the penciller memory. For other SST files, the breakdown between merge_lists and other activity in file creation is: + +![](pics/MergeTimeCompare.png) + +This indicates that 90% of the time is being spent running merge_lists, which is a CPU intensive process. Also that CPU intensive process lasts on average for 2s per host every second. + +This test was run on servers with 4 CPU cores (with 8 threads). Depending on accounting for CPU time, the merge_lists process during merge appears to be consuming somewhere between 25% and 50% of CPU time in thee test. diff --git a/docs/pics/.DS_Store b/docs/pics/.DS_Store index 2e5fc06..6e130a2 100644 Binary files a/docs/pics/.DS_Store and b/docs/pics/.DS_Store differ diff --git a/docs/pics/Level0CreateTimeSplit.png b/docs/pics/Level0CreateTimeSplit.png new file mode 100644 index 0000000..ba3d658 Binary files /dev/null and b/docs/pics/Level0CreateTimeSplit.png differ diff --git a/docs/pics/MergeTimeCompare.png b/docs/pics/MergeTimeCompare.png new file mode 100644 index 0000000..143c48d Binary files /dev/null and b/docs/pics/MergeTimeCompare.png differ diff --git a/docs/pics/PerHostTotalFileCreateTime.png b/docs/pics/PerHostTotalFileCreateTime.png new file mode 100644 index 0000000..ab24d4d Binary files /dev/null and b/docs/pics/PerHostTotalFileCreateTime.png differ