5.7. Performance Tracing

If you have enabled performance profiling from the server-side, you can run detailed performance traces of the operations that you execute on your cluster. This will provide you with a detailed, step-by-step trace of tje low-level operations, and are usually useful when you are debugging together with your Solution Architect.

If you have enabled statistics in conjunction with performance traces, you will get additional performance trace metrics in your statistics.

To use performance traces from the QuasarDB shell, use the enable_perf_trace command as follows:

$ qdbsh
quasardb shell version 3.5.0master build ce779a9 2019-10-23 00:04:01 +0000
Copyright (c) 2009-2019 quasardb. All rights reserved.
Need some help? Check out our documentation here:  https://doc.quasardb.net

qdbsh > enable_perf_trace
qdbsh > create table testable(col1 int64, col2 double)

*** begin performance trace

total time: 175 us

- function + ts.create_root - 175 us [100.00 %]
           |
           |              data received:         0 us - delta:         0 us [00.00 % - 00.00 %]
           |     deserialization starts:         2 us - delta:         2 us [01.14 % - 01.14 %]
           |       deserialization ends:         7 us - delta:         5 us [02.86 % - 02.86 %]
           |             entering chord:         9 us - delta:         2 us [01.14 % - 01.14 %]
           |                   dispatch:        14 us - delta:         5 us [02.86 % - 02.86 %]
           |     deserialization starts:        24 us - delta:        10 us [05.71 % - 05.71 %]
           |       deserialization ends:        26 us - delta:         2 us [01.14 % - 01.14 %]
           |          processing starts:        28 us - delta:         2 us [01.14 % - 01.14 %]
           |      entry trimming starts:        79 us - delta:        51 us [29.14 % - 29.14 %]
           |        entry trimming ends:        81 us - delta:         2 us [01.14 % - 01.14 %]
           |     content writing starts:        82 us - delta:         1 us [00.57 % - 00.57 %]
           |       content writing ends:       141 us - delta:        59 us [33.71 % - 33.71 %]
           |       entry writing starts:       141 us - delta:         0 us [00.00 % - 00.00 %]
           |         entry writing ends:       172 us - delta:        31 us [17.71 % - 17.71 %]
           |            processing ends:       175 us - delta:         3 us [01.71 % - 01.71 %]

*** end performance trace

In the trace above, for example, we can see the performance trace of the CREATE TABLE statement, and get a detailed idea of where it’s spending most of its time. In this case, the total operation lasted 175 microseconds, and a detailed breakdown of the low level function timings.