Thermostat/DevPerfLogging

From IcedTea

Jump to: navigation, search

Thermostat Home

Thermostat perf logging

In latest HG head (rev 914a5b12e044) and better thermostat itself comes with a little bit of code which does logging of performance metrics. Currently it only logs storage related stats. This page describes how this logging can be enabled and later be analyzed using thermostat's perf log analyzer.

First, we create a perflog-logging.properties file with the following content:

com.redhat.thermostat.handlers=java.util.logging.FileHandler

java.util.logging.FileHandler.pattern = %h/.thermostat/logs/thermostat_perflog.log
java.util.logging.FileHandler.limit = 5000000
java.util.logging.FileHandler.append = false
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter

com.redhat.thermostat.level=PERFLOG

First note that the FileHandler needs to have java.util.logging.SimpleFormatter configured. Without that explicit configuration j.u.l will generate XML logs which are no use to us since we'd like to run our log file analyzer on the produced logs. Ideally, we'd use LogFormatter comming from Thermostat itself, but it's currently not in a thermostat boot jar. See bug 1945 for details. Next we copy this file which is in logging.properties format to THERMOSTAT_HOME/etc/logging.properties

$ cp perflog-logging.properties $THERMOSTAT_HOME/etc/logging.properties

This will make thermostat log to $HOME/.thermostat/logs/thermostat_perflog.log. If one process has that file locked then FileHandler will create another file with a unique number as suffix: e.g. $HOME/.thermostat/logs/thermostat_perflog.log.1

Next we run thermostat web-storage-service and thermostat storage-profile. The latter we do since it will generate some queries and we'd like to get some query info as well. A different command which uses queries will do as well.

$ thermostat web-storage-service
$ echo -e 'client-tester\ntester' | ./distribution/target/image/bin/thermostat storage-profile -i 10

This will produce files $HOME/.thermostat/logs/thermostat_perflog.log (web-storage-service) and $HOME/.thermostat/logs/thermostat_perflog.log.1 (storage-profile). Next we combine those files in order to run the analyzer on that file.

$ cat $HOME/.thermostat/logs/thermostat_perflog.log{,.1} > $HOME/.thermostat/logs/thermostat_perflog_combined.log

Finally we run the analyzer on that file.

$ java -jar $THERMOSTAT_HOME/dev/perflog-analyzer/target/thermostat-perflog-analyzer-*.jar $HOME/.thermostat/logs/thermostat_perflog_combined.log

The output should look similar to this.

Statistics for log file: $HOME/.thermostat/logs/thermostat_perflog_combined.log
Total of 9512 records analyzed.

Queue size stats (2344 records): 97(max) 1(min) 8.64(avg)

Statement statistics (2412 records): 23 distinct statements (69 reads, 2343 writes)

Statement details (sorted by avg exec time):
Total #: 4, 15032µs (min), 139691µs (max), 52969.50µs (avg), DESCRIPTOR: ADD vm-info SET 'agentId' = ?s , 'vmId' = ?s , 'vmPid' = ?i , 'startTimeStamp' = ?l , 'stopTimeStamp' = ?l , 'javaVersion' = ?s , 'javaHome' = ?s , 'mainClass' = ?s , 'javaCommandLine' = ?s , 'vmName' = ?s , 'vmArguments' = ?s , 'vmInfo' = ?s , 'vmVersion' = ?s , 'propertiesAsArray' = ?p[ , 'environmentAsArray' = ?p[ , 'loadedNativeLibraries' = ?s[ , 'uid' = ?l , 'username' = ?s
Total #: 1, 33780µs (min), 33780µs (max), 33780.00µs (avg), DESCRIPTOR: ADD agent-config SET 'agentId' = ?s , 'startTime' = ?l , 'stopTime' = ?l , 'alive' = ?b , 'configListenAddress' = ?s
Total #: 1, 33319µs (min), 33319µs (max), 33319.00µs (avg), DESCRIPTOR: ADD host-info SET 'agentId' = ?s , 'hostname' = ?s , 'osName' = ?s , 'osKernel' = ?s , 'cpuModel' = ?s , 'cpuCount' = ?i , 'totalMemory' = ?l
Total #: 30, 4313µs (min), 50713µs (max), 16466.23µs (avg), DESCRIPTOR: QUERY storage-profile
Total #: 91, 3362µs (min), 166965µs (max), 10070.91µs (avg), DESCRIPTOR: ADD numa-stat SET 'agentId' = ?s , 'timeStamp' = ?l , 'nodeStats' = ?p[
Total #: 39, 4193µs (min), 88453µs (max), 8519.64µs (avg), DESCRIPTOR: QUERY-COUNT storage-profile
Total #: 10, 4709µs (min), 22078µs (max), 8487.10µs (avg), DESCRIPTOR: ADD backend-info SET 'agentId' = ?s , 'name' = ?s , 'description' = ?s , 'observeNewJvm' = ?b , 'pids' = ?i[ , 'active' = ?b , 'orderValue' = ?i
Total #: 1, 7686µs (min), 7686µs (max), 7686.00µs (avg), DESCRIPTOR: UPDATE vm-info SET 'stopTimeStamp' = ?l WHERE 'vmId' = ?s
Total #: 90, 3551µs (min), 13305µs (max), 7603.86µs (avg), DESCRIPTOR: ADD cpu-stats SET 'agentId' = ?s , 'perProcessorUsage' = ?d[ , 'timeStamp' = ?l
Total #: 4, 5226µs (min), 14389µs (max), 7558.00µs (avg), DESCRIPTOR: REPLACE vm-thread-capabilities SET 'agentId' = ?s , 'vmId' = ?s , 'supportedFeaturesList' = ?s[ WHERE 'agentId' = ?s AND 'vmId' = ?s
Total #: 265, 3177µs (min), 117577µs (max), 7362.27µs (avg), DESCRIPTOR: ADD vm-cpu-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'cpuLoad' = ?d
Total #: 268, 3722µs (min), 23167µs (max), 7240.21µs (avg), DESCRIPTOR: ADD vm-memory-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'generations' = ?p[
Total #: 364, 3056µs (min), 90919µs (max), 6483.79µs (avg), DESCRIPTOR: REPLACE network-info SET 'agentId' = ?s , 'interfaceName' = ?s , 'ip4Addr' = ?s , 'ip6Addr' = ?s WHERE 'agentId' = ?s AND 'interfaceName' = ?s
Total #: 91, 3566µs (min), 17435µs (max), 5993.59µs (avg), DESCRIPTOR: ADD memory-stats SET 'agentId' = ?s , 'timeStamp' = ?l , 'total' = ?l , 'free' = ?l , 'buffers' = ?l , 'cached' = ?l , 'swapTotal' = ?l , 'swapFree' = ?l , 'commitLimit' = ?l
Total #: 536, 2953µs (min), 17898µs (max), 5767.84µs (avg), DESCRIPTOR: ADD vm-gc-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'collectorName' = ?s , 'runCount' = ?l , 'wallTime' = ?l
Total #: 1, 5671µs (min), 5671µs (max), 5671.00µs (avg), DESCRIPTOR: ADD numa-host-info SET 'agentId' = ?s , 'numNumaNodes' = ?i
Total #: 7, 3694µs (min), 13124µs (max), 5526.86µs (avg), DESCRIPTOR: REMOVE storage-profile
Total #: 268, 3077µs (min), 19892µs (max), 5519.11µs (avg), DESCRIPTOR: ADD vm-class-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'loadedClasses' = ?l
Total #: 9, 3144µs (min), 8455µs (max), 5207.56µs (avg), DESCRIPTOR: ADD vm-thread-harvesting SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'harvesting' = ?b
Total #: 10, 3688µs (min), 10134µs (max), 5052.50µs (avg), DESCRIPTOR: UPDATE storage-profile  SET   'string' = ?s WHERE 'long' = ?l
Total #: 311, 3429µs (min), 12271µs (max), 4563.29µs (avg), DESCRIPTOR: ADD storage-profile SET 'agentId' = ?s ,    'string' = ?s ,    'long' = ?l
Total #: 10, 3011µs (min), 4098µs (max), 3368.00µs (avg), DESCRIPTOR: REMOVE backend-info WHERE 'name' = ?s
Total #: 1, 2976µs (min), 2976µs (max), 2976.00µs (avg), DESCRIPTOR: REMOVE agent-config WHERE 'agentId' = ?s

Showing backing storage info as well - by passing --show-backing (or equivalent) to the analyzer, output looks like this:

Statistics for log file: $HOME/.thermostat/logs/thermostat_perflog_combined.log
Total of 9512 records analyzed.

Queue size stats (2344 records): 97(max) 1(min) 8.64(avg)

Statement statistics (2412 records): 23 distinct statements (69 reads, 2343 writes)

Statement details (sorted by avg exec time):
Total #: 4, 15032µs (min), 139691µs (max), 52969.50µs (avg), DESCRIPTOR: ADD vm-info SET 'agentId' = ?s , 'vmId' = ?s , 'vmPid' = ?i , 'startTimeStamp' = ?l , 'stopTimeStamp' = ?l , 'javaVersion' = ?s , 'javaHome' = ?s , 'mainClass' = ?s , 'javaCommandLine' = ?s , 'vmName' = ?s , 'vmArguments' = ?s , 'vmInfo' = ?s , 'vmVersion' = ?s , 'propertiesAsArray' = ?p[ , 'environmentAsArray' = ?p[ , 'loadedNativeLibraries' = ?s[ , 'uid' = ?l , 'username' = ?s
Total #: 1, 33780µs (min), 33780µs (max), 33780.00µs (avg), DESCRIPTOR: ADD agent-config SET 'agentId' = ?s , 'startTime' = ?l , 'stopTime' = ?l , 'alive' = ?b , 'configListenAddress' = ?s
Total #: 1, 33319µs (min), 33319µs (max), 33319.00µs (avg), DESCRIPTOR: ADD host-info SET 'agentId' = ?s , 'hostname' = ?s , 'osName' = ?s , 'osKernel' = ?s , 'cpuModel' = ?s , 'cpuCount' = ?i , 'totalMemory' = ?l
Total #: 30, 4313µs (min), 50713µs (max), 16466.23µs (avg), DESCRIPTOR: QUERY storage-profile
Total #: 91, 3362µs (min), 166965µs (max), 10070.91µs (avg), DESCRIPTOR: ADD numa-stat SET 'agentId' = ?s , 'timeStamp' = ?l , 'nodeStats' = ?p[
Total #: 39, 4193µs (min), 88453µs (max), 8519.64µs (avg), DESCRIPTOR: QUERY-COUNT storage-profile
Total #: 10, 4709µs (min), 22078µs (max), 8487.10µs (avg), DESCRIPTOR: ADD backend-info SET 'agentId' = ?s , 'name' = ?s , 'description' = ?s , 'observeNewJvm' = ?b , 'pids' = ?i[ , 'active' = ?b , 'orderValue' = ?i
Total #: 1, 7686µs (min), 7686µs (max), 7686.00µs (avg), DESCRIPTOR: UPDATE vm-info SET 'stopTimeStamp' = ?l WHERE 'vmId' = ?s
Total #: 90, 3551µs (min), 13305µs (max), 7603.86µs (avg), DESCRIPTOR: ADD cpu-stats SET 'agentId' = ?s , 'perProcessorUsage' = ?d[ , 'timeStamp' = ?l
Total #: 4, 5226µs (min), 14389µs (max), 7558.00µs (avg), DESCRIPTOR: REPLACE vm-thread-capabilities SET 'agentId' = ?s , 'vmId' = ?s , 'supportedFeaturesList' = ?s[ WHERE 'agentId' = ?s AND 'vmId' = ?s
Total #: 265, 3177µs (min), 117577µs (max), 7362.27µs (avg), DESCRIPTOR: ADD vm-cpu-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'cpuLoad' = ?d
Total #: 268, 3722µs (min), 23167µs (max), 7240.21µs (avg), DESCRIPTOR: ADD vm-memory-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'generations' = ?p[
Total #: 364, 3056µs (min), 90919µs (max), 6483.79µs (avg), DESCRIPTOR: REPLACE network-info SET 'agentId' = ?s , 'interfaceName' = ?s , 'ip4Addr' = ?s , 'ip6Addr' = ?s WHERE 'agentId' = ?s AND 'interfaceName' = ?s
Total #: 91, 3566µs (min), 17435µs (max), 5993.59µs (avg), DESCRIPTOR: ADD memory-stats SET 'agentId' = ?s , 'timeStamp' = ?l , 'total' = ?l , 'free' = ?l , 'buffers' = ?l , 'cached' = ?l , 'swapTotal' = ?l , 'swapFree' = ?l , 'commitLimit' = ?l
Total #: 536, 2953µs (min), 17898µs (max), 5767.84µs (avg), DESCRIPTOR: ADD vm-gc-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'collectorName' = ?s , 'runCount' = ?l , 'wallTime' = ?l
Total #: 1, 5671µs (min), 5671µs (max), 5671.00µs (avg), DESCRIPTOR: ADD numa-host-info SET 'agentId' = ?s , 'numNumaNodes' = ?i
Total #: 7, 3694µs (min), 13124µs (max), 5526.86µs (avg), DESCRIPTOR: REMOVE storage-profile
Total #: 268, 3077µs (min), 19892µs (max), 5519.11µs (avg), DESCRIPTOR: ADD vm-class-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'loadedClasses' = ?l
Total #: 9, 3144µs (min), 8455µs (max), 5207.56µs (avg), DESCRIPTOR: ADD vm-thread-harvesting SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'harvesting' = ?b
Total #: 10, 3688µs (min), 10134µs (max), 5052.50µs (avg), DESCRIPTOR: UPDATE storage-profile  SET   'string' = ?s WHERE 'long' = ?l
Total #: 311, 3429µs (min), 12271µs (max), 4563.29µs (avg), DESCRIPTOR: ADD storage-profile SET 'agentId' = ?s ,    'string' = ?s ,    'long' = ?l
Total #: 10, 3011µs (min), 4098µs (max), 3368.00µs (avg), DESCRIPTOR: REMOVE backend-info WHERE 'name' = ?s
Total #: 1, 2976µs (min), 2976µs (max), 2976.00µs (avg), DESCRIPTOR: REMOVE agent-config WHERE 'agentId' = ?s

Queue size stats (2344 records): 9(max) 0(min) 1.08(avg)

Statement statistics (2412 records): 23 distinct statements (69 reads, 2343 writes)

Statement details (sorted by avg exec time):
Total #: 1, 97640987ns (min), 97640987ns (max), 97640987.00ns (avg), DESCRIPTOR: ADD host-info SET 'agentId' = ?s , 'hostname' = ?s , 'osName' = ?s , 'osKernel' = ?s , 'cpuModel' = ?s , 'cpuCount' = ?i , 'totalMemory' = ?l
Total #: 1, 94002093ns (min), 94002093ns (max), 94002093.00ns (avg), DESCRIPTOR: UPDATE vm-info SET 'stopTimeStamp' = ?l WHERE 'vmId' = ?s
Total #: 4, 852613ns (min), 52987700ns (max), 14205291.00ns (avg), DESCRIPTOR: REPLACE vm-thread-capabilities SET 'agentId' = ?s , 'vmId' = ?s , 'supportedFeaturesList' = ?s[ WHERE 'agentId' = ?s AND 'vmId' = ?s
Total #: 4, 1735733ns (min), 38094766ns (max), 12515861.50ns (avg), DESCRIPTOR: ADD vm-info SET 'agentId' = ?s , 'vmId' = ?s , 'vmPid' = ?i , 'startTimeStamp' = ?l , 'stopTimeStamp' = ?l , 'javaVersion' = ?s , 'javaHome' = ?s , 'mainClass' = ?s , 'javaCommandLine' = ?s , 'vmName' = ?s , 'vmArguments' = ?s , 'vmInfo' = ?s , 'vmVersion' = ?s , 'propertiesAsArray' = ?p[ , 'environmentAsArray' = ?p[ , 'loadedNativeLibraries' = ?s[ , 'uid' = ?l , 'username' = ?s
Total #: 7, 356673ns (min), 36869680ns (max), 5950105.86ns (avg), DESCRIPTOR: REMOVE storage-profile
Total #: 1, 5440162ns (min), 5440162ns (max), 5440162.00ns (avg), DESCRIPTOR: ADD numa-host-info SET 'agentId' = ?s , 'numNumaNodes' = ?i
Total #: 9, 380176ns (min), 33098764ns (max), 4198556.44ns (avg), DESCRIPTOR: ADD vm-thread-harvesting SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'harvesting' = ?b
Total #: 10, 378921ns (min), 25208350ns (max), 3361938.80ns (avg), DESCRIPTOR: ADD backend-info SET 'agentId' = ?s , 'name' = ?s , 'description' = ?s , 'observeNewJvm' = ?b , 'pids' = ?i[ , 'active' = ?b , 'orderValue' = ?i
Total #: 1, 2464126ns (min), 2464126ns (max), 2464126.00ns (avg), DESCRIPTOR: ADD agent-config SET 'agentId' = ?s , 'startTime' = ?l , 'stopTime' = ?l , 'alive' = ?b , 'configListenAddress' = ?s
Total #: 91, 403418ns (min), 99723676ns (max), 1917349.66ns (avg), DESCRIPTOR: ADD memory-stats SET 'agentId' = ?s , 'timeStamp' = ?l , 'total' = ?l , 'free' = ?l , 'buffers' = ?l , 'cached' = ?l , 'swapTotal' = ?l , 'swapFree' = ?l , 'commitLimit' = ?l
Total #: 265, 339209ns (min), 74413577ns (max), 1777722.97ns (avg), DESCRIPTOR: ADD vm-cpu-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'cpuLoad' = ?d
Total #: 268, 405611ns (min), 100688919ns (max), 1700083.83ns (avg), DESCRIPTOR: ADD vm-memory-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'generations' = ?p[
Total #: 268, 339885ns (min), 76188148ns (max), 1680305.87ns (avg), DESCRIPTOR: ADD vm-class-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'loadedClasses' = ?l
Total #: 91, 379072ns (min), 49552698ns (max), 1585488.19ns (avg), DESCRIPTOR: ADD numa-stat SET 'agentId' = ?s , 'timeStamp' = ?l , 'nodeStats' = ?p[
Total #: 536, 306919ns (min), 251297160ns (max), 1459764.03ns (avg), DESCRIPTOR: ADD vm-gc-stats SET 'agentId' = ?s , 'vmId' = ?s , 'timeStamp' = ?l , 'collectorName' = ?s , 'runCount' = ?l , 'wallTime' = ?l
Total #: 90, 391213ns (min), 32805635ns (max), 1366194.90ns (avg), DESCRIPTOR: ADD cpu-stats SET 'agentId' = ?s , 'perProcessorUsage' = ?d[ , 'timeStamp' = ?l
Total #: 39, 298571ns (min), 29242593ns (max), 1325926.44ns (avg), DESCRIPTOR: QUERY-COUNT storage-profile
Total #: 364, 361666ns (min), 12354603ns (max), 975139.35ns (avg), DESCRIPTOR: REPLACE network-info SET 'agentId' = ?s , 'interfaceName' = ?s , 'ip4Addr' = ?s , 'ip6Addr' = ?s WHERE 'agentId' = ?s AND 'interfaceName' = ?s
Total #: 10, 470917ns (min), 1172051ns (max), 603725.30ns (avg), DESCRIPTOR: UPDATE storage-profile  SET   'string' = ?s WHERE 'long' = ?l
Total #: 311, 258184ns (min), 6776173ns (max), 522094.39ns (avg), DESCRIPTOR: ADD storage-profile SET 'agentId' = ?s ,    'string' = ?s ,    'long' = ?l
Total #: 10, 323595ns (min), 618863ns (max), 454907.30ns (avg), DESCRIPTOR: REMOVE backend-info WHERE 'name' = ?s
Total #: 1, 429813ns (min), 429813ns (max), 429813.00ns (avg), DESCRIPTOR: REMOVE agent-config WHERE 'agentId' = ?s
Total #: 30, 10425ns (min), 2296763ns (max), 89122.17ns (avg), DESCRIPTOR: QUERY storage-profile

Note that the second section of the output pertains to backing storage (unit is nano seconds). Also, we expect the number of reads/writes to match between front and backing storage statistics.

Personal tools