Captured on Ubuntu 14.04 VM on MacOS 10.13.4 on Macbook Pro 2017 running on battery The following results were obtained by running ztrace_perf with MetricEvent proto that used varints instead of fixed int (see end of this file). Therefore, the results include overhead associated with bit shifts involved in constructing varints. Note that the max latency in the very batch is significantly higher than that for subsequent batches. This is expected to come from memory allocation penalties in first-time sizing of the underlying dynamic buffers. I0601 08:43:41.643437 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.643582 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.643589 28743 ztrace_perf.cpp:78] max = 259 microsec I0601 08:43:41.643592 28743 ztrace_perf.cpp:79] mean = 0.38299 microsec I0601 08:43:41.643616 28743 ztrace_perf.cpp:80] stdev = 1.16498 microsec I0601 08:43:41.643620 28743 ztrace_perf.cpp:81] sum (debug) = 38299 microsec I0601 08:43:41.649716 28743 ztrace_perf.cpp:89] serialized size = 927134 B [5707 microsec] I0601 08:43:41.683807 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.683845 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.683847 28743 ztrace_perf.cpp:78] max = 65 microsec I0601 08:43:41.683850 28743 ztrace_perf.cpp:79] mean = 0.30807 microsec I0601 08:43:41.683858 28743 ztrace_perf.cpp:80] stdev = 0.630542 microsec I0601 08:43:41.683861 28743 ztrace_perf.cpp:81] sum (debug) = 30807 microsec I0601 08:43:41.689532 28743 ztrace_perf.cpp:89] serialized size = 916221 B [5568 microsec] I0601 08:43:41.723183 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.723227 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.723230 28743 ztrace_perf.cpp:78] max = 43 microsec I0601 08:43:41.723232 28743 ztrace_perf.cpp:79] mean = 0.30396 microsec I0601 08:43:41.723242 28743 ztrace_perf.cpp:80] stdev = 0.502999 microsec I0601 08:43:41.723244 28743 ztrace_perf.cpp:81] sum (debug) = 30396 microsec I0601 08:43:41.728817 28743 ztrace_perf.cpp:89] serialized size = 914689 B [5459 microsec] I0601 08:43:41.761880 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.761916 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.761919 28743 ztrace_perf.cpp:78] max = 37 microsec I0601 08:43:41.761921 28743 ztrace_perf.cpp:79] mean = 0.29831 microsec I0601 08:43:41.761929 28743 ztrace_perf.cpp:80] stdev = 0.509491 microsec I0601 08:43:41.761932 28743 ztrace_perf.cpp:81] sum (debug) = 29831 microsec I0601 08:43:41.766785 28743 ztrace_perf.cpp:89] serialized size = 914114 B [4758 microsec] I0601 08:43:41.800392 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.800434 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.800438 28743 ztrace_perf.cpp:78] max = 32 microsec I0601 08:43:41.800441 28743 ztrace_perf.cpp:79] mean = 0.30095 microsec I0601 08:43:41.800451 28743 ztrace_perf.cpp:80] stdev = 0.511468 microsec I0601 08:43:41.800453 28743 ztrace_perf.cpp:81] sum (debug) = 30095 microsec I0601 08:43:41.805358 28743 ztrace_perf.cpp:89] serialized size = 913525 B [4808 microsec] I0601 08:43:41.837553 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.837587 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.837589 28743 ztrace_perf.cpp:78] max = 57 microsec I0601 08:43:41.837591 28743 ztrace_perf.cpp:79] mean = 0.29087 microsec I0601 08:43:41.837600 28743 ztrace_perf.cpp:80] stdev = 0.510788 microsec I0601 08:43:41.837604 28743 ztrace_perf.cpp:81] sum (debug) = 29087 microsec I0601 08:43:41.842339 28743 ztrace_perf.cpp:89] serialized size = 912195 B [4642 microsec] I0601 08:43:41.875499 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.875542 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.875545 28743 ztrace_perf.cpp:78] max = 48 microsec I0601 08:43:41.875547 28743 ztrace_perf.cpp:79] mean = 0.29577 microsec I0601 08:43:41.875557 28743 ztrace_perf.cpp:80] stdev = 0.50836 microsec I0601 08:43:41.875560 28743 ztrace_perf.cpp:81] sum (debug) = 29577 microsec I0601 08:43:41.880708 28743 ztrace_perf.cpp:89] serialized size = 912376 B [5054 microsec] I0601 08:43:41.913409 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.913451 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.913455 28743 ztrace_perf.cpp:78] max = 29 microsec I0601 08:43:41.913457 28743 ztrace_perf.cpp:79] mean = 0.29255 microsec I0601 08:43:41.913468 28743 ztrace_perf.cpp:80] stdev = 0.514533 microsec I0601 08:43:41.913471 28743 ztrace_perf.cpp:81] sum (debug) = 29255 microsec I0601 08:43:41.918700 28743 ztrace_perf.cpp:89] serialized size = 912453 B [5134 microsec] I0601 08:43:41.951382 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.951416 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.951419 28743 ztrace_perf.cpp:78] max = 27 microsec I0601 08:43:41.951422 28743 ztrace_perf.cpp:79] mean = 0.29525 microsec I0601 08:43:41.951431 28743 ztrace_perf.cpp:80] stdev = 0.493211 microsec I0601 08:43:41.951434 28743 ztrace_perf.cpp:81] sum (debug) = 29525 microsec I0601 08:43:41.956315 28743 ztrace_perf.cpp:89] serialized size = 913488 B [4785 microsec] I0601 08:43:41.989370 28743 ztrace_perf.cpp:75] ZTRACE latency stats (100000 events): I0601 08:43:41.989416 28743 ztrace_perf.cpp:77] min = 0 microsec I0601 08:43:41.989419 28743 ztrace_perf.cpp:78] max = 42 microsec I0601 08:43:41.989423 28743 ztrace_perf.cpp:79] mean = 0.29298 microsec I0601 08:43:41.989432 28743 ztrace_perf.cpp:80] stdev = 0.523567 microsec I0601 08:43:41.989434 28743 ztrace_perf.cpp:81] sum (debug) = 29298 microsec I0601 08:43:41.995688 28743 ztrace_perf.cpp:89] serialized size = 911420 B [6142 microsec] // Ref: https://docs.google.com/document/d/1dmx1qpFRE6PdJldqO6QhJ-AGb6qGUCAim9PASrIuNa0 syntax = "proto2"; package zoox.metrics.proto; // NOTE: though the spec prescribes smaller size integers for the fields below, // we rely on ProtoBuf's "varint" compression for the types below. // Use this for each timing-observation message MetricEvent { optional uint32 timestamp_microsec = 1; optional uint32 location_16b = 2; // Use only lower 16b! // use sparingly and only for short-lived debug !!! optional string annotations = 3; extensions 10000 to 19999; } // Use this to collect timing observations over an entire tick message PerTickMetrics { optional uint32 tick_id = 1; optional uint64 origin_timestamp_ns = 2; repeated MetricEvent events = 3; }