[CONF] Apache Qpid: Java Broker Analysis Tools (page edited)

[confluence]

Page Edited : qpid : Java Broker Analysis Tools Java Broker Analysis Tools has been edited by Martin Ritchie (Jun 23, 2009). (View changes) Content: Analysis Tools This page contains details of the broker analysis tools available as part of the Performance Test package, Overview To better understand the performance of the Java broker this collection of tools have been gathered to perform analysis on a variety of logging that the broker can produce. Looking solely at the throughput values from our performance suite is not sufficient to tell us that the broker's performance has increased. Currently it the scripts monitor: Heap Usage via verbose GC logging GC Duration via verbose GC logging CPU Usage via batch mode top Additional logging can be added to gather data as required. The processing of the resulting log files from the broker run can then processed and using gnuplot graphs of the data are generated. Monitoring To better understand how the broker is performing there are some easy things we can start monitoring. Verbose GC/Heap Usage CPU Usage GC / Heap Usage Enabling verbose gc will allow the broker to provide us with a log file that details GC operation. SO we can get a better handle on the impact of GC on the performance of the broker. Enabling is done by providing a few additional values via QPID_OPTS: -Xloggc:<gc log file> -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps This will result in a gc log file that shows all GCs performed. Of inititial interest is the extraction of: Heap Usage ( Max Allocated, Pre/Post GC Usage) GC Count (Incremental, Full) GC Duration (Incremental, Full, Total) As we gather this information a better internal view of the broker in opperation can be built. When changes are made to the broker this data should allow us to determine how the changes have affected the GC and memory profile. CPU Usage In addition to the GC and Memory profiling available via the verbose gc settings monitoring the CPU usage via top is a quick and easy way to view the cpu utilisation of the broker. Using the following top command we can monitor a give broker and adjust the time interval in which we record the CPU usage. $ top -d $monitor_rate -S -c -p $broker_pid -b > broker_cpu.log Scripting To make life easier and to allow for future automated testing the following monitoring scripts have been added to the 'perftest' package: monitor-broker.sh stop-monitored-broker.sh monitor-broker.sh The monitor-broker.sh script current starts the following processes: The broker with additional QPID_OPTS for gc logging Top to monitoring the CPU usage To run this script a number of parameters are requried: Usage ./monitor-broker.sh <Path to Test Broker> <LOG DIR> <CPU Monitor Rate (s)> [Additional options to pass to Qpid broker startup] The first parameter is the path to a qpid-broker package, or at least a directory that contains an executable broker. The <LOG DIR> is a path that must not exist (this is checked) for all the log files to be collected for this monitored startup process. The verbose gc, broker log, std out/err and PID files will be written to this directory. The rate at which top will run to monitor this broker is the third value, any value here that is valid for top's '-d' parameter is valid here. Finally the remainder of the command line is passed directly to the qpid-server start up so additional log configuration or configuration can be provided here. NOTE: if providing custom log4j setup please ensure that the log file is written to QPID_WORK as this is set to the <LOG DIR> value. This will ensure that all the log files for the testing run are located in a single directory for easy later processing. The pids of the broker and top are written to a *.pid file in the LOG_DIR. These are also used by the stop-monitored-broker.sh script to ensure clean shutdown. If additional processes are desired to be run if they write a PID into LOG_DIR/*.pid then they will be shutdown with the stop script. stop-monitored-broker.sh This is a simple script that takes the <LOG DIR> as its only parameter. It then looks in this directory for all '.pid' files and uses their contained pid value to execute a 'kill' command. If all processes have not stopped within 3 seconds then a 'kill -9' is executed. runTests.sh The final script in the monitoring package currently is 'runTest.sh' this simplifies the execution of a suite of tests. The script takes three parameters: Usage ./runTests.sh <Path to Test Pack> <LOG DIR> <TEST LIST FILE> As with the monitor-broker.sh the first parameter is the path to the qpid-test package that can be build using the Build Creator. The test simply looks for a path that has a bin which will be used to execute your test lists. The LOG_DIR path again is requied not to exist on startup to ensure we have a clean result set. The results of each test run are instructed to be written here by adding '-o <LOG_DIR> --csv' to the executed test. Finally the 'Test List File' is a plain text file containing a single command per line to execute. The entries here should at least respond to the '-o' parameter to ensure that their output is collected in the LOG_DIR. An example test file might contain something link: TQBT-AA-Qpid-01.sh -d10M TTBT-AA-Qpid-01.sh -d10M The two test scripts are assumed to exist in thee <path to test pack>/bin directory. Processing Result Processing The raw output from the test runs will need to be processed so that we can generated graphs of the cpu and gc profile during the test. The output will require processing so that the information can be graphed. The tools used to perform this extraction will also be a deliverable from this work so that future investigation can provide comparable output. Example Output The output from the gc logs will look like this: 0.584: [Full GC (System) 0.584: [CMS: 0K->1442K(63872K), 0.0551280 secs] 8062K->1442K(83008K), [CMS Perm : 10996K->10988K(21248K)], 0.0552370 secs] 10.414: [GC 10.414: [ParNew: 19136K->2112K(19136K), 0.0149810 secs] 51068K->45443K(83008K), 0.0150890 secs] 10.436: [GC [1 CMS-initial-mark: 43331K(63872K)] 46210K(83008K), 0.0013220 secs] 10.437: [CMS-concurrent-mark-start] 10.530: [CMS-concurrent-mark: 0.074/0.093 secs] 10.530: [CMS-concurrent-preclean-start] 10.531: [CMS-concurrent-preclean: 0.001/0.001 secs] 10.531: [CMS-concurrent-abortable-preclean-start] 10.598: [GC 10.598: [ParNew: 19136K->2112K(19136K), 0.0110880 secs] 62467K->51273K(83008K), 0.0111980 secs] 10.717: [CMS-concurrent-abortable-preclean: 0.004/0.186 secs] 10.719: [GC[YG occupancy: 17386 K (19136 K)]10.719: [Rescan (parallel) , 0.0077250 secs]10.726: [weak refs processing, 0.0006200 secs] [1CMS-remark: 49161K(63872K)] 66548K(83008K), 0.0084590 secs] 10.727: [CMS-concurrent-sweep-start] 10.733: [CMS-concurrent-sweep: 0.005/0.005 secs] 10.733: [CMS-concurrent-reset-start] 10.740: [CMS-concurrent-reset: 0.007/0.007 secs] 44.211: [Full GC 44.211: [CMS44.302: [CMS-concurrent-sweep: 0.111/0.114 secs] (concurrent mode failure): 918418K->13583K(961816K), 0.2009920 secs] 937554K->13583K(980952K), [CMS Perm : 17859K->17830K(29832K)], 0.201 The output from the top command will look like this: top - 11:51:03 up 15 days, 7:38, 1 user, load average: 0.00, 0.19, 1.05 Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie Cpu(s): 0.6% us, 0.1% sy, 0.0% ni, 99.2% id, 0.0% wa, 0.0% hi, 0.1% si Mem: 4040220k total, 4011240k used, 28980k free, 195564k buffers Swap: 16386292k total, 0k used, 16386292k free, 2423116k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 28778 ritchiem 16 0 1310m 1.1g 8712 S 0 28.0 36:54.22 java

Powered by Atlassian Confluence (Version: 2.2.9 Build:#527 Sep 07, 2006) - Bug/feature request

Unsubscribe or edit your notifications preferences

--------------------------------------------------------------------- Apache Qpid - AMQP Messaging Implementation Project: http://qpid.apache.org Use/Interact: mailto:commits-subscr...@qpid.apache.org