kudu-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From ale...@apache.org
Subject [kudu] branch master updated: [benchmarks] added a few 'perf stat' metrics
Date Tue, 11 Aug 2020 01:23:43 GMT
This is an automated email from the ASF dual-hosted git repository.

alexey pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/kudu.git


The following commit(s) were added to refs/heads/master by this push:
     new 1c5a04f  [benchmarks] added a few 'perf stat' metrics
1c5a04f is described below

commit 1c5a04f7774f348b3c9fc4fd39de98c858c87c5f
Author: Alexey Serbin <alexey@apache.org>
AuthorDate: Mon Aug 3 14:29:54 2020 -0700

    [benchmarks] added a few 'perf stat' metrics
    
    Added an ability to run most of the micro-benchmarks under 'perf stat'
    and record the following counters:
      * instructions per cycle
      * CPU utilization
      * branch misses
    
    These Performance Monitoring Counters (PMCs) are relatively stable
    in terms of 'run to run' with the same binary at the same machine
    (under 5% pct deviation).  They provide an extra coverage in addition
    to the application-specific metrics directly output by the tests.  The
    introduced PMCs show how effective the code is in using available
    hardware resources, whether the code is instruction or memory bound,
    etc. For example, see [1] and [2] how to interpret values
    of the instructions-per-cycle (IPC) performance counters.
    
    It seems these new performance metrics cannot be used for release-gating
    decisions, but they are useful in tracking improvements and regressions
    in the code, especially when updating common sub-components like
    third-party libraries, etc.
    
    For each of the mentioned performance counters, a graph is generated
    with data points for all the tests run under 'perf stat'.
    
    As of now, the following existing tests are not run under `perf stat`
    and corresponding TODOs are added:
      * tests based on external test mini-cluster (need to track performance
        of spawn kudu-tserver and kudu-master processes, but that's not
        available yet, need to implement that)
      * full_stack-insert-scan-test (custom-tailored --perf_stat_scan
        provision are not working for some reason, need fix that)
    
    To disable the collection of these performance counters, set
    RUN_PERF_STAT to 0 (it's set to 1 by default).
    
    [1] http://www.brendangregg.com/blog/2017-05-09/cpu-utilization-is-wrong.html
    [2] http://www.brendangregg.com/blog/2017-05-04/the-pmcs-of-ec2.html
    
    Change-Id: Ib742ffbaabca96c2ac455481313348da2133ff6e
    Reviewed-on: http://gerrit.cloudera.org:8080/16284
    Reviewed-by: Andrew Wong <awong@cloudera.com>
    Tested-by: Alexey Serbin <aserbin@cloudera.com>
---
 src/kudu/scripts/benchmarks.sh | 362 +++++++++++++++++++++++++++--------------
 1 file changed, 241 insertions(+), 121 deletions(-)

diff --git a/src/kudu/scripts/benchmarks.sh b/src/kudu/scripts/benchmarks.sh
index 6154c7d..5a16d3a 100755
--- a/src/kudu/scripts/benchmarks.sh
+++ b/src/kudu/scripts/benchmarks.sh
@@ -43,7 +43,7 @@ LOCAL_STATS_BASE="local-stats"
 NUM_MT_TABLET_TESTS=5
 MT_TABLET_TEST=mt-tablet-test
 RPC_BENCH_TEST=RpcBenchBenchmark
-CBTREE_TEST=cbtree-test
+CBTREE_TEST=ConcurrentBTreeScan
 BLOOM_TEST=BloomfileBenchmark
 MT_BLOOM_TEST=MultithreadedBloomfileBenchmark
 WIRE_PROTOCOL_TEST=WireProtocolBenchmark
@@ -80,6 +80,17 @@ HTML_FILE="benchmarks.html"
 # Most tests will run this many times.
 NUM_SAMPLES=${NUM_SAMPLES:-10}
 
+# Whether to run the benchmarks under 'perf stat', recording and plotting
+# the statistics collected by 'perf stat'.  The 'perf stat' has the
+# least overhead among all sub-commands of the 'perf' suite (e.g., see
+# http://www.brendangregg.com/perf.html).
+RUN_PERF_STAT=${RUN_PERF_STAT:-1}
+if [ $RUN_PERF_STAT -ne 0 -o "$RUN_PERF_STAT" = x"yes" ]; then
+  PERF_STAT="perf stat"
+else
+  PERF_STAT=""
+fi
+
 ################################################################
 # Global variables
 ################################################################
@@ -103,6 +114,24 @@ usage_and_die() {
   exit 1
 }
 
+perf_stat_enabled() {
+  if [ -z "$PERF_STAT" ]; then
+    return 1
+  fi
+  return 0
+}
+
+# Ensure the necessary performance tools are present.
+check_tools() {
+  if perf_stat_enabled; then
+    # Check for 'perf' assuming the 'stat' sub-tool is always available.
+    if ! which perf > /dev/null; then
+      return 1
+    fi
+  fi
+  return 0
+}
+
 ensure_cpu_scaling() {
   $BASE_DIR/src/kudu/scripts/ensure_cpu_scaling.sh "$@"
 }
@@ -143,7 +172,7 @@ write_img_plot() {
   local y_axis_label="$3"
   # Rscript fails when there's only a header, so just skip
   if [ `wc -l $input_file | cut -d ' ' -f1` -gt 1 ]; then
-    Rscript jobs_runtime.R $input_file $test_name "$y_axis_label"
+    Rscript jobs_runtime.R "$input_file" "$test_name" "$y_axis_label"
   fi
 }
 
@@ -191,8 +220,10 @@ run_benchmarks() {
   mkdir -p "$LOGDIR"
   mkdir -p "$OUTDIR"
 
+  export KUDU_ALLOW_SLOW_TESTS=true
+
   # run all of the variations of mt-tablet-test
-  ./build/latest/bin/mt-tablet-test \
+  $PERF_STAT ./build/latest/bin/mt-tablet-test \
     --gtest_filter=\*DoTestAllAtOnce\* \
     --num_counter_threads=0 \
     --tablet_test_flush_threshold_mb=32 \
@@ -204,20 +235,26 @@ run_benchmarks() {
 
   # run rpc-bench test 5 times. 10 seconds per run
   for i in $(seq 1 $NUM_SAMPLES); do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/rpc-bench \
-      --gtest_filter=*BenchmarkCalls &> $LOGDIR/$RPC_BENCH_TEST$i.log
+    $PERF_STAT ./build/latest/bin/rpc-bench \
+      --gtest_filter=*BenchmarkCalls \
+      &> $LOGDIR/$RPC_BENCH_TEST$i.log
   done
 
   # run cbtree-test 5 times. 20 seconds per run
   for i in $(seq 1 $NUM_SAMPLES); do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/cbtree-test \
-      --gtest_filter=TestCBTree.TestScanPerformance &> $LOGDIR/${CBTREE_TEST}$i.log
+    $PERF_STAT ./build/latest/bin/cbtree-test \
+      --gtest_filter=TestCBTree.TestScanPerformance \
+      &> $LOGDIR/${CBTREE_TEST}$i.log
   done
 
   # run bloomfile-test 5 times. ~3.3 seconds per run
   for i in $(seq 1 $NUM_SAMPLES); do
-    ./build/latest/bin/bloomfile-test --benchmark_queries=10000000 --bloom_size_bytes=32768
\
-      --n_keys=100000 --gtest_filter=*Benchmark &> $LOGDIR/$BLOOM_TEST$i.log
+    $PERF_STAT ./build/latest/bin/bloomfile-test \
+      --gtest_filter=*Benchmark \
+      --benchmark_queries=10000000 \
+      --bloom_size_bytes=32768 \
+      --n_keys=100000 \
+      &> $LOGDIR/$BLOOM_TEST$i.log
   done
 
   # run mt-bloomfile-test 5 times. 20-30 seconds per run.
@@ -225,46 +262,55 @@ run_benchmarks() {
   # set the cache capacity to be only 100M to ensure that the cache
   # churns a lot.
   for i in $(seq 1 $NUM_SAMPLES); do
-    ./build/latest/bin/mt-bloomfile-test --benchmark_queries=2000000 --bloom_size_bytes=4096
\
-      --n_keys=150000000 --block_cache_capacity_mb=100 &> $LOGDIR/$MT_BLOOM_TEST$i.log
+    $PERF_STAT ./build/latest/bin/mt-bloomfile-test \
+      --benchmark_queries=2000000 --bloom_size_bytes=4096 \
+      --n_keys=150000000 --block_cache_capacity_mb=100 \
+      &> $LOGDIR/$MT_BLOOM_TEST$i.log
   done
 
   # run wire_protocol-test 5 times.
   #
   # We run the non-null 10-column benchmark, selecting all rows.
   for i in $(seq 1 $NUM_SAMPLES); do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/wire_protocol-test --gtest_filter=*Benchmark/10_int64_non_null_sel_100pct
\
+    $PERF_STAT ./build/latest/bin/wire_protocol-test \
+      --gtest_filter=*Benchmark/10_int64_non_null_sel_100pct \
       &> $LOGDIR/$WIRE_PROTOCOL_TEST$i.log
   done
 
   # run compaction-test 5 times, 6 seconds each
   for i in $(seq 1 $NUM_SAMPLES); do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/compaction-test \
-      --gtest_filter=TestCompaction.BenchmarkMerge* &> $LOGDIR/${COMPACT_MERGE_BENCH}$i.log
+    $PERF_STAT ./build/latest/bin/compaction-test \
+      --gtest_filter=TestCompaction.BenchmarkMerge* \
+      &> $LOGDIR/${COMPACT_MERGE_BENCH}$i.log
   done
 
   # run memrowset benchmark 5 times, ~10 seconds per run
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    ./build/latest/bin/memrowset-test --roundtrip_num_rows=10000000 \
-        --gtest_filter=\*InsertCount\* &> $LOGDIR/${MEMROWSET_BENCH}$i.log
+    $PERF_STAT ./build/latest/bin/memrowset-test \
+      --roundtrip_num_rows=10000000 \
+      --gtest_filter=\*InsertCount\* \
+      &> $LOGDIR/${MEMROWSET_BENCH}$i.log
   done
 
   # Run single-threaded TS insert latency benchmark, 5-6 seconds per run
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/tablet_server-test \
+    $PERF_STAT ./build/latest/bin/tablet_server-test \
       --gtest_filter=*MicroBench* \
       --single_threaded_insert_latency_bench_warmup_rows=1000 \
-      --single_threaded_insert_latency_bench_insert_rows=10000 &> $LOGDIR/${TS_INSERT_LATENCY}$i.log
+      --single_threaded_insert_latency_bench_insert_rows=10000 \
+      &> $LOGDIR/${TS_INSERT_LATENCY}$i.log
   done
 
   # Run multi-threaded TS insert benchmark
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=1 build/latest/bin/tablet_server-stress-test \
-      --num_inserts_per_thread=30000 -runtime_secs=0 &> $LOGDIR/${TS_8THREAD_BENCH}$i.log
+    $PERF_STAT ./build/latest/bin/tablet_server-stress-test \
+      --num_inserts_per_thread=30000 -runtime_secs=0 \
+      &> $LOGDIR/${TS_8THREAD_BENCH}$i.log
   done
 
   # Run full stack scan/insert test using MRS only, ~26s each
   for i in $(seq 1 $NUM_SAMPLES) ; do
+    # TODO(aserbin): fix --perf_stat_scan and enable stats collection
     ./build/latest/bin/full_stack-insert-scan-test \
       --gtest_filter=FullStackInsertScanTest.MRSOnlyStressTest \
       --concurrent_inserts=50 \
@@ -275,6 +321,7 @@ run_benchmarks() {
 
   # Run full stack scan/insert test with disk, ~50s each
   for i in $(seq 1 $NUM_SAMPLES) ; do
+    # TODO(aserbin): fix --perf_stat_scan and enable stats collection
     ./build/latest/bin/full_stack-insert-scan-test \
       --gtest_filter=FullStackInsertScanTest.WithDiskStressTest \
       --concurrent_inserts=50 \
@@ -286,6 +333,8 @@ run_benchmarks() {
   # Run dense storage node test, ~150s each.
   #
   # Needs to run as root for measure_startup_drop_caches.
+  # TODO(aserbin): add performance counter collection once it's possible to run
+  #                external minicluster's components under 'perf stat'
   for i in $(seq 1 $NUM_SAMPLES) ; do
     sudo ./build/latest/bin/dense_node-itest \
       --num_seconds=60 \
@@ -299,7 +348,7 @@ run_benchmarks() {
   # Run BlockingQueue concurrency test with 3 writers and 3 readers,
   # (i.e. symmetric in number of readers/writers), no non-blocking writers.
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/blocking_queue-test \
+    $PERF_STAT ./build/latest/bin/blocking_queue-test \
       --gtest_filter=BlockingQueueMultiThreadPerfTest.RequestRates \
       --num_blocking_writers=3 \
       --num_blocking_readers=3 \
@@ -310,7 +359,7 @@ run_benchmarks() {
   # Run BlockingQueue concurrency test with 3 writers
   # (2 blocking, 1 non-blocking) and 1 reader.
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/blocking_queue-test \
+    $PERF_STAT ./build/latest/bin/blocking_queue-test \
       --gtest_filter=BlockingQueueMultiThreadPerfTest.RequestRates \
       --num_blocking_writers=2 \
       --num_blocking_readers=1 \
@@ -320,14 +369,14 @@ run_benchmarks() {
 
   # Run ConcurrentGetTableSchemaTest.RPC with and without authz.
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/master-test \
+    $PERF_STAT ./build/latest/bin/master-test \
       --gtest_filter='*/ConcurrentGetTableSchemaTest.Rpc/*' \
       &> $LOGDIR/${GET_TABLE_SCHEMA_RPC}$i.log
   done
 
   # Run ConcurrentGetTableSchemaTest.DirectMethodCall with and without authz.
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/master-test \
+    $PERF_STAT ./build/latest/bin/master-test \
       --gtest_filter='*/ConcurrentGetTableSchemaTest.DirectMethodCall/*' \
       &> $LOGDIR/${GET_TABLE_SCHEMA_DIRECT_CALL}$i.log
   done
@@ -335,35 +384,52 @@ run_benchmarks() {
   # Run GetTableLocationsBenchmark, with and without cache.
   for capacity_mb in 0 32 ; do
     for i in $(seq 1 $NUM_SAMPLES) ; do
-      KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/table_locations-itest \
+      $PERF_STAT ./build/latest/bin/table_locations-itest \
         --gtest_filter=TableLocationsTest.GetTableLocationsBenchmark \
         --rpc_num_service_threads=8 \
         --benchmark_num_threads=12 \
         --table_locations_cache_capacity_mb=$capacity_mb \
-        &> $LOGDIR/${GET_TABLE_LOCATIONS_RPC}_${capacity_mb}_$i.log
+        &> $LOGDIR/${GET_TABLE_LOCATIONS_RPC}_${capacity_mb}$i.log
     done
   done
 
   # Run GetTableLocationsBenchmarkFunctionCall, with and without cache.
   for capacity_mb in 0 32 ; do
     for i in $(seq 1 $NUM_SAMPLES) ; do
-      KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/table_locations-itest \
+      $PERF_STAT ./build/latest/bin/table_locations-itest \
         --gtest_filter=TableLocationsTest.GetTableLocationsBenchmarkFunctionCall \
         --benchmark_num_threads=12 \
         --table_locations_cache_capacity_mb=$capacity_mb \
-        &> $LOGDIR/${GET_TABLE_LOCATIONS_DIRECT_CALL}_${capacity_mb}_$i.log
+        &> $LOGDIR/${GET_TABLE_LOCATIONS_DIRECT_CALL}_${capacity_mb}$i.log
     done
   done
 
   # Run SameTabletConcurrentWritesTest.InsertsOnly with 16 inserter threads.
   for i in $(seq 1 $NUM_SAMPLES) ; do
-    KUDU_ALLOW_SLOW_TESTS=true ./build/latest/bin/same_tablet_concurrent_writes-itest \
+    $PERF_STAT ./build/latest/bin/same_tablet_concurrent_writes-itest \
       --gtest_filter='SameTabletConcurrentWritesTest.InsertsOnly' \
       --num_inserter_threads=16 \
       &> $LOGDIR/${SAME_TABLET_CONCURRENT_WRITES}$i.log
   done
 }
 
+parse_and_record_perf_stats() {
+  if ! perf_stat_enabled; then
+    return
+  fi
+  local build_id=$1
+  local test_id=$2
+  local iter=$3
+  local log=$4
+
+  local ins_per_cycle=$(grep -o '# .* ins.* per cycle' $log | awk '{print $2}')
+  record_result $build_id perf_stat_ins_per_cycle_${test_id} $iter $ins_per_cycle
+  local cpu_util=$(grep -o '# .* CPUs utilized' $log | awk '{print $2}')
+  record_result $build_id perf_stat_cpu_util_${test_id} $iter $cpu_util
+  local branch_misses=$(grep -o '# .* of all branches' $log | awk '{print $2}' | sed 's/%//g')
+  record_result $build_id perf_stat_branch_misses_${test_id} $iter $branch_misses
+}
+
 parse_and_record_all_results() {
   local BUILD_IDENTIFIER="$1"
 
@@ -388,56 +454,68 @@ parse_and_record_all_results() {
     timing=`sed -n "${linenumber}p" $LOGDIR/${MT_TABLET_TEST_TIMINGS}.txt`
     record_result $BUILD_IDENTIFIER MultiThreadedTabletTest_$i 1 `echo $timing / 1000 | bc
-l`
   done
+  parse_and_record_perf_stats $BUILD_IDENTIFIER $MT_TABLET_TEST 1 $LOGDIR/${MT_TABLET_TEST}.log
 
   # parse out the real time from: "Time spent Insert 10000000 keys: real 16.438s user 16.164s
 sys 0.229s"
   for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "Time spent Insert" $LOGDIR/${CBTREE_TEST}$i.log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ConcurrentBTreeScanInsert $i $real
-  done
+    local id=$CBTREE_TEST
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
 
-  for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "not frozen" $LOGDIR/${CBTREE_TEST}$i.log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ConcurrentBTreeScanNotFrozen $i $real
-  done
+    real=`grep "Time spent Insert" $log | ./parse_real_out.sh`
+    record_result $BUILD_IDENTIFIER ${id}Insert $i $real
 
-  for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "(frozen" $LOGDIR/${CBTREE_TEST}$i.log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ConcurrentBTreeScanFrozen $i $real
+    real=`grep "not frozen" $log | ./parse_real_out.sh`
+    record_result $BUILD_IDENTIFIER ${id}NotFrozen $i $real
+
+    real=`grep "(frozen" $log | ./parse_real_out.sh`
+    record_result $BUILD_IDENTIFIER ${id}Frozen $i $real
   done
 
   # parse out the real time from "Time spent with overlap: real 0.557s user 0.546s sys 0.010s"
   for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "with overlap" $LOGDIR/${COMPACT_MERGE_BENCH}$i.log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${COMPACT_MERGE_BENCH}${WITH_OVERLAP} $i $real
-  done
+    local id=$COMPACT_MERGE_BENCH
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
 
-  for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "without overlap" $LOGDIR/${COMPACT_MERGE_BENCH}$i.log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${COMPACT_MERGE_BENCH}${NO_OVERLAP} $i $real
+    real=`grep "with overlap" $log | ./parse_real_out.sh`
+    record_result $BUILD_IDENTIFIER ${id}${WITH_OVERLAP} $i $real
+
+    real=`grep "without overlap" $log | ./parse_real_out.sh`
+    record_result $BUILD_IDENTIFIER ${id}${NO_OVERLAP} $i $real
   done
 
   # parse out time from MRS benchmarks
   for i in $(seq 1 $NUM_SAMPLES); do
-    log=$LOGDIR/${MEMROWSET_BENCH}$i.log
+    local id=$MEMROWSET_BENCH
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+
     real=`grep "Time spent Inserting" $log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${MEMROWSET_BENCH}${INSERT} $i $real
+    record_result $BUILD_IDENTIFIER ${id}${INSERT} $i $real
     real=`grep "Time spent Scanning rows where none" $log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${MEMROWSET_BENCH}${SCAN_NONE_COMMITTED} $i $real
+    record_result $BUILD_IDENTIFIER ${id}${SCAN_NONE_COMMITTED} $i $real
     real=`grep "Time spent Scanning rows where all" $log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${MEMROWSET_BENCH}${SCAN_ALL_COMMITTED} $i $real
+    record_result $BUILD_IDENTIFIER ${id}${SCAN_ALL_COMMITTED} $i $real
   done
 
   # Parse out the real time from: "Time spent Running 10000000 queries: real 3.281s  user
3.273s sys 0.000s"
   for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "Time spent Running" $LOGDIR/$BLOOM_TEST$i.log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER $BLOOM_TEST $i $real
+    local id=$BLOOM_TEST
+    local log=$LOGDIR/${id}${i}.log
+    local real=`grep "Time spent Running" $log | ./parse_real_out.sh`
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+    record_result $BUILD_IDENTIFIER $id $i $real
   done
 
   # Parse out the real time from: "Time spent Running 2000000 queries: real 28.193s user
26.903s sys 1.032s"
   # Many threads output their value, we keep the last;
   for i in $(seq 1 $NUM_SAMPLES); do
-    real=`grep "Time spent Running" $LOGDIR/$MT_BLOOM_TEST$i.log | tail -n1 | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER $MT_BLOOM_TEST $i $real
+    local id=$MT_BLOOM_TEST
+    local log=$LOGDIR/${id}${i}.log
+    local real=`grep "Time spent Running" $log | tail -n1 | ./parse_real_out.sh`
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+    record_result $BUILD_IDENTIFIER $id $i $real
   done
 
   # Parse out row-wise rate of cycles/cell from:
@@ -445,73 +523,88 @@ parse_and_record_all_results() {
   # Parse out the columnar rate of cycles/cell from:
   #   "Converting 10_int64_non_null to PB (method columnar) row select rate 1: 1.313369 cycles/cell"
   for i in $(seq 1 $NUM_SAMPLES); do
-    real_rowwise=`grep "Converting.*to PB (method row-wise)" $LOGDIR/$WIRE_PROTOCOL_TEST$i.log
| sed 's|^.*: \([[:digit:].]*\) cycles/cell$|\1|'`
-    record_result $BUILD_IDENTIFIER $WIRE_PROTOCOL_TEST $i $real_rowwise
+    local id=$WIRE_PROTOCOL_TEST
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+
+    local real_rowwise=`grep "Converting.*to PB (method row-wise)" $log | sed 's|^.*: \([[:digit:].]*\)
cycles/cell$|\1|'`
+    record_result $BUILD_IDENTIFIER $id $i $real_rowwise
 
-    real_colwise=`grep "Converting.*to PB (method columnar)" $LOGDIR/$WIRE_PROTOCOL_TEST$i.log
| sed 's|^.*: \([[:digit:].]*\) cycles/cell$|\1|'`
-    record_result $BUILD_IDENTIFIER ${WIRE_PROTOCOL_TEST}_columnar $i $real_colwise
+    local real_colwise=`grep "Converting.*to PB (method columnar)" $log | sed 's|^.*: \([[:digit:].]*\)
cycles/cell$|\1|'`
+    record_result $BUILD_IDENTIFIER ${id}_columnar $i $real_colwise
   done
 
   # parse the rate out of: "I1009 15:00:30.023576 27043 rpc-bench.cc:108] Reqs/sec:     
   84404.4"
   for i in $(seq 1 $NUM_SAMPLES); do
-    rate=`grep Reqs $LOGDIR/$RPC_BENCH_TEST$i.log | cut -d ":" -f 5 | tr -d ' '`
-    record_result $BUILD_IDENTIFIER $RPC_BENCH_TEST $i $rate
+    local id=$RPC_BENCH_TEST
+    local log=$LOGDIR/${id}${i}.log
+    local rate=`grep Reqs $log | cut -d ":" -f 5 | tr -d ' '`
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+    record_result $BUILD_IDENTIFIER $id $i $rate
   done
 
   # parse latency numbers from single-threaded tserver benchmark
   for i in $(seq 1 $NUM_SAMPLES); do
+    local id=$TS_INSERT_LATENCY
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
     for metric in min mean percentile_95 percentile_99 percentile_99_9 ; do
-      val=$(grep "\"$metric\": " $LOGDIR/${TS_INSERT_LATENCY}$i.log | awk '{print $2}' |
sed -e 's/,//')
-      record_result $BUILD_IDENTIFIER ${TS_INSERT_LATENCY}_$metric $i $val
+      val=$(grep "\"$metric\": " $log | awk '{print $2}' | sed -e 's/,//')
+      record_result $BUILD_IDENTIFIER ${id}_${metric} $i $val
     done
   done
 
   # parse latency and throughput numbers from multi-threaded tserver benchmark
   for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${TS_8THREAD_BENCH}$i.log
+    local id=$TS_8THREAD_BENCH
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
     for metric in min mean percentile_95 percentile_99 percentile_99_9 ; do
       val=$(grep "\"$metric\": " $log | awk '{print $2}' | sed -e 's/,//')
-      record_result $BUILD_IDENTIFIER ${TS_8THREAD_BENCH}_${metric}_latency $i $val
+      record_result $BUILD_IDENTIFIER ${id}_${metric}_latency $i $val
     done
     rate=$(grep -o 'Throughput.*' $log | awk '{print $2}')
-    record_result $BUILD_IDENTIFIER ${TS_8THREAD_BENCH}_throughput $i $rate
+    record_result $BUILD_IDENTIFIER ${id}_throughput $i $rate
     rate=$(grep -o 'CPU efficiency.*' $log | awk '{print $3}')
-    record_result $BUILD_IDENTIFIER ${TS_8THREAD_BENCH}_cpu_efficiency $i $rate
+    record_result $BUILD_IDENTIFIER ${id}_cpu_efficiency $i $rate
   done
 
   # parse scan timings for scans and inserts with MRS only
   for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${FS_SCANINSERT_MRS}$i.log
+    local id=$FS_SCANINSERT_MRS
+    local log=$LOGDIR/${id}${i}.log
     insert=`grep "Time spent concurrent inserts" $log | ./parse_real_out.sh`
     scan_full=`grep "Time spent full schema scan" $log | ./parse_real_out.sh`
     scan_str=`grep "Time spent String projection" $log | ./parse_real_out.sh`
     scan_int32=`grep "Time spent Int32 projection" $log | ./parse_real_out.sh`
     scan_int64=`grep "Time spent Int64 projection" $log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_MRS}_insert $i $insert
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_MRS}_scan_full $i $scan_full
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_MRS}_scan_str $i $scan_str
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_MRS}_scan_int32 $i $scan_int32
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_MRS}_scan_int64 $i $scan_int64
+    record_result $BUILD_IDENTIFIER ${id}_insert $i $insert
+    record_result $BUILD_IDENTIFIER ${id}_scan_full $i $scan_full
+    record_result $BUILD_IDENTIFIER ${id}_scan_str $i $scan_str
+    record_result $BUILD_IDENTIFIER ${id}_scan_int32 $i $scan_int32
+    record_result $BUILD_IDENTIFIER ${id}_scan_int64 $i $scan_int64
   done
 
   # parse scan timings for scans and inserts with disk
   for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${FS_SCANINSERT_DISK}$i.log
+    local id=$FS_SCANINSERT_DISK
+    local log=$LOGDIR/${id}${i}.log
     insert=`grep "Time spent concurrent inserts" $log | ./parse_real_out.sh`
     scan_full=`grep "Time spent full schema scan" $log | ./parse_real_out.sh`
     scan_str=`grep "Time spent String projection" $log | ./parse_real_out.sh`
     scan_int32=`grep "Time spent Int32 projection" $log | ./parse_real_out.sh`
     scan_int64=`grep "Time spent Int64 projection" $log | ./parse_real_out.sh`
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_DISK}_insert $i $insert
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_DISK}_scan_full $i $scan_full
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_DISK}_scan_str $i $scan_str
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_DISK}_scan_int32 $i $scan_int32
-    record_result $BUILD_IDENTIFIER ${FS_SCANINSERT_DISK}_scan_int64 $i $scan_int64
+    record_result $BUILD_IDENTIFIER ${id}_insert $i $insert
+    record_result $BUILD_IDENTIFIER ${id}_scan_full $i $scan_full
+    record_result $BUILD_IDENTIFIER ${id}_scan_str $i $scan_str
+    record_result $BUILD_IDENTIFIER ${id}_scan_int32 $i $scan_int32
+    record_result $BUILD_IDENTIFIER ${id}_scan_int64 $i $scan_int64
   done
 
   # Parse timings and thread count
   for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${DENSE_NODE_ITEST}$i.log
+    local id=$DENSE_NODE_ITEST
+    local log=$LOGDIR/${id}${i}.log
     num_threads=`grep threads_running $log | cut -d ":" -f 5 | tr -d ' '`
     num_blocks=`grep log_block_manager_blocks_under_management $log | cut -d ":" -f 5 | tr
-d ' '`
     num_bytes=`grep log_block_manager_bytes_under_management $log | cut -d ":" -f 5 | tr
-d ' '`
@@ -528,65 +621,68 @@ parse_and_record_all_results() {
     time_restarting_tserver=`grep "Time spent restarting tserver" $log | ./parse_real_out.sh`
     time_bootstrapping_tablets=`grep "Time spent bootstrapping tablets" $log | ./parse_real_out.sh`
     set -e
-    record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_num_threads $i $num_threads
-    record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_num_blocks $i $num_blocks
-    record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_num_bytes $i $num_bytes
-    record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_num_containers $i $num_containers
-    record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_num_full_containers $i $num_full_containers
+    record_result $BUILD_IDENTIFIER ${id}_num_threads $i $num_threads
+    record_result $BUILD_IDENTIFIER ${id}_num_blocks $i $num_blocks
+    record_result $BUILD_IDENTIFIER ${id}_num_bytes $i $num_bytes
+    record_result $BUILD_IDENTIFIER ${id}_num_containers $i $num_containers
+    record_result $BUILD_IDENTIFIER ${id}_num_full_containers $i $num_full_containers
     if [ -n "$time_restarting_tserver" ]; then
-      record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_time_restarting_tserver $i $time_restarting_tserver
+      record_result $BUILD_IDENTIFIER ${id}_time_restarting_tserver $i $time_restarting_tserver
     fi
     if [ -n "$time_bootstrapping_tablets" ]; then
-      record_result $BUILD_IDENTIFIER ${DENSE_NODE_ITEST}_time_bootstrapping_tablets $i $time_bootstrapping_tablets
+      record_result $BUILD_IDENTIFIER ${id}_time_bootstrapping_tablets $i $time_bootstrapping_tablets
     fi
 
   done
 
   # Parse out total call rate and record the results for BlockingQueue test.
-  for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${BLOCKING_QUEUE_SYMMETRIC_TEST}$i.log
-    rate=$(grep -o 'total rate: .* calls/sec' $log | awk '{print $3}')
-    record_result $BUILD_IDENTIFIER ${BLOCKING_QUEUE_SYMMETRIC_TEST}_total_call_rate $i $rate
-
-    local log=$LOGDIR/${BLOCKING_QUEUE_NON_SYMMETRIC_TEST}$i.log
-    rate=$(grep -o 'total rate: .* calls/sec' $log | awk '{print $3}')
-    record_result $BUILD_IDENTIFIER ${BLOCKING_QUEUE_NON_SYMMETRIC_TEST}_total_call_rate
$i $rate
+  for id in $BLOCKING_QUEUE_SYMMETRIC_TEST $BLOCKING_QUEUE_NON_SYMMETRIC_TEST; do
+    for i in $(seq 1 $NUM_SAMPLES); do
+      local log=$LOGDIR/${id}${i}.log
+      parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+      local rate=$(grep -o 'total rate: .* calls/sec' $log | awk '{print $3}')
+      record_result $BUILD_IDENTIFIER ${id}_total_call_rate $i $rate
+    done
   done
 
   # Parse out request rate and record the results for ConcurrentGetTableSchemaTest test.
-  for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${GET_TABLE_SCHEMA_RPC}$i.log
-    rate=$(grep -o 'GetTableSchema RPC: .* req/sec (authz disabled)' $log | awk '{print $3}')
-    record_result $BUILD_IDENTIFIER ${GET_TABLE_SCHEMA_RPC}_no_authz_req_rate $i $rate
-    rate=$(grep -o 'GetTableSchema RPC: .* req/sec (authz enabled)' $log | awk '{print $3}')
-    record_result $BUILD_IDENTIFIER ${GET_TABLE_SCHEMA_RPC}_authz_req_rate $i $rate
-
-    local log=$LOGDIR/${GET_TABLE_SCHEMA_DIRECT_CALL}$i.log
-    rate=$(grep -o 'GetTableSchema function: .* req/sec (authz disabled)' $log | awk '{print
$3}')
-    record_result $BUILD_IDENTIFIER ${GET_TABLE_SCHEMA_DIRECT_CALL}_no_authz_req_rate $i
$rate
-    rate=$(grep -o 'GetTableSchema function: .* req/sec (authz enabled)' $log | awk '{print
$3}')
-    record_result $BUILD_IDENTIFIER ${GET_TABLE_SCHEMA_DIRECT_CALL}_authz_req_rate $i $rate
+  for id in $GET_TABLE_SCHEMA_RPC $GET_TABLE_SCHEMA_DIRECT_CALL; do
+    for i in $(seq 1 $NUM_SAMPLES); do
+      local log=$LOGDIR/${id}${i}.log
+      parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+      rate=$(grep -o 'GetTableSchema .*: .* req/sec (authz disabled)' $log | awk '{print
$3}')
+      record_result $BUILD_IDENTIFIER ${id}_no_authz_req_rate $i $rate
+      rate=$(grep -o 'GetTableSchema .*: .* req/sec (authz enabled)' $log | awk '{print $3}')
+      record_result $BUILD_IDENTIFIER ${id}_authz_req_rate $i $rate
+    done
   done
 
   # Parse out request rate and record the results for GetTableLocationsBenchmark{FunctionCall}.
   for capacity_mb in 0 32 ; do
     for i in $(seq 1 $NUM_SAMPLES); do
-      local log=$LOGDIR/${GET_TABLE_LOCATIONS_RPC}_${capacity_mb}_${i}.log
+      local id=${GET_TABLE_LOCATIONS_RPC}_${capacity_mb}
+      local log=$LOGDIR/${id}${i}.log
+      parse_and_record_perf_stats $BUILD_IDENTIFIER ${id} $i $log
       rate=$(grep -o 'GetTableLocations RPC: .* req/sec' $log | awk '{print $3}')
-      record_result $BUILD_IDENTIFIER ${GET_TABLE_LOCATIONS_RPC}_${capacity_mb}_req_rate
$i $rate
+      record_result $BUILD_IDENTIFIER ${id}_req_rate $i $rate
 
-      local log=$LOGDIR/${GET_TABLE_LOCATIONS_DIRECT_CALL}_${capacity_mb}_${i}.log
+      local id=${GET_TABLE_LOCATIONS_DIRECT_CALL}_${capacity_mb}
+      local log=$LOGDIR/${id}${i}.log
+      parse_and_record_perf_stats $BUILD_IDENTIFIER ${id} $i $log
       rate=$(grep -o 'GetTableLocations function call: .* req/sec' $log | awk '{print $4}')
-      record_result $BUILD_IDENTIFIER ${GET_TABLE_LOCATIONS_DIRECT_CALL}_${capacity_mb}_req_rate
$i $rate
+      record_result $BUILD_IDENTIFIER ${id}_req_rate $i $rate
     done
   done
 
   for i in $(seq 1 $NUM_SAMPLES); do
-    local log=$LOGDIR/${SAME_TABLET_CONCURRENT_WRITES}$i.log
+    local id=$SAME_TABLET_CONCURRENT_WRITES
+    local log=$LOGDIR/${id}${i}.log
+    parse_and_record_perf_stats $BUILD_IDENTIFIER $id $i $log
+
     rate=$(grep -o 'write RPC request rate: .* req/sec' $log | awk '{print $5}')
+    record_result $BUILD_IDENTIFIER ${id}_req_rate $i $rate
     overflows=$(grep -o 'total count of RPC queue overflows: .*' $log | awk '{print $7}')
-    record_result $BUILD_IDENTIFIER ${SAME_TABLET_CONCURRENT_WRITES}_req_rate $i $rate
-    record_result $BUILD_IDENTIFIER ${SAME_TABLET_CONCURRENT_WRITES}_overflows $i $overflows
+    record_result $BUILD_IDENTIFIER ${id}_overflows $i $overflows
   done
 
   popd
@@ -629,9 +725,26 @@ load_and_generate_plot() {
   if [ -z "$y_axis_label" ]; then
     local y_axis_label="runtime (sec)"
   fi
-  local fpath=${OUTDIR}/${plot_name}.tsv
-  load_stats "$test_name" > $fpath
-  write_img_plot $fpath $plot_name "$y_axis_label"
+  local plot_file=${OUTDIR}/${plot_name}.tsv
+  load_stats "$test_name" > $plot_file
+  write_img_plot $plot_file $plot_name "$y_axis_label"
+}
+
+load_and_generate_perf_stat_plots() {
+  local id="perf_stat_ins_per_cycle"
+  local plot_file=${OUTDIR}/${id}.tsv
+  load_stats "${id}_%" > $plot_file
+  write_img_plot $plot_file "perf-stat-instructions-per-CPU-cycle" "instructions per cycle"
+
+  local id="perf_stat_cpu_util"
+  local plot_file=${OUTDIR}/${id}.tsv
+  load_stats "${id}_%" > $plot_file
+  write_img_plot $plot_file "perf-stat-cpu-utilization" "CPUs utilized"
+
+  local id="perf_stat_branch_misses"
+  local plot_file=${OUTDIR}/${id}.tsv
+  load_stats "${id}_%" > $plot_file
+  write_img_plot $plot_file "perf-stat-branch-misses" "% of all branches"
 }
 
 load_stats_and_generate_plots() {
@@ -641,9 +754,9 @@ load_stats_and_generate_plots() {
 
   load_and_generate_plot "%MultiThreadedTabletTest%" mt-tablet-test-runtime
 
-  load_and_generate_plot ConcurrentBTreeScanInsert cb-tree-insert
-  load_and_generate_plot ConcurrentBTreeScanNotFrozen cb-ctree-not-frozen
-  load_and_generate_plot ConcurrentBTreeScanFrozen cb-ctree-frozen
+  load_and_generate_plot ${CBTREE_TEST}Insert cb-tree-insert
+  load_and_generate_plot ${CBTREE_TEST}NotFrozen cb-ctree-not-frozen
+  load_and_generate_plot ${CBTREE_TEST}Frozen cb-ctree-frozen
 
   load_and_generate_plot "${COMPACT_MERGE_BENCH}%" compact-merge-bench
 
@@ -682,8 +795,8 @@ load_stats_and_generate_plots() {
   load_and_generate_plot "${GET_TABLE_SCHEMA_DIRECT_CALL}_authz_req_rate" get-table-schema-dc-authz
"function call rate (req/sec)"
   load_and_generate_plot "${GET_TABLE_SCHEMA_DIRECT_CALL}_no_authz_req_rate" get-table-schema-dc-no-authz
"function call rate (req/sec)"
 
-  load_and_generate_plot "${GET_TABLE_LOCATIONS_RPC}%_req_rate" get-table-locations-rpc "RPC
rate (req/sec)"
-  load_and_generate_plot "${GET_TABLE_LOCATIONS_DIRECT_CALL}%_req_rate" get-table-locations-dc
"function call rate (req/sec)"
+  load_and_generate_plot "${GET_TABLE_LOCATIONS_RPC}%_req_rate" get-table-locations-rpc
+  load_and_generate_plot "${GET_TABLE_LOCATIONS_DIRECT_CALL}%_req_rate" get-table-locations-dc
 
   load_and_generate_plot "${SAME_TABLET_CONCURRENT_WRITES}_req_rate" same-tablet-concurrent-writes-rate
"RPC rate (req/sec)"
   load_and_generate_plot "${SAME_TABLET_CONCURRENT_WRITES}_overflows" same-tablet-concurrent-writes-overflows
"RPC queue overflows (total count)"
@@ -695,6 +808,9 @@ load_stats_and_generate_plots() {
     write_mttablet_img_plots $OUTDIR/test$i.tsv test$i || true
   done
 
+  # Generate performance counters plots for all tests run under 'perf stat'.
+  load_and_generate_perf_stat_plots
+
   if [ "${BENCHMARK_MODE}" = "${MODE_JENKINS}" ]; then
     ################################################################
     # Plot the separately-recorded TPCH and YCSB graphs as well
@@ -796,11 +912,15 @@ OUTDIR="$BASE_DIR/$OUT_DIR_NAME"
 
 # Ensure we are in KUDU_HOME
 if [ ! -f "$BASE_DIR/LICENSE.txt" ]; then
-  set +x
   echo "Error: must run from top of Kudu source tree"
   usage_and_die
 fi
 
+if ! check_tools; then
+  echo "Error: could not find necessary tools to run benchmarks"
+  exit 1
+fi
+
 # Set up environment.
 ulimit -m $[3000*1000]
 ulimit -c unlimited   # gather core dumps


Mime
View raw message