How to dynamically parse Jira performance log used for gathering jmx statistics

Related content

  • No related content found

Still need help?

The Atlassian Community is here for you.

Ask the community

Platform Notice: Data Center Only - This article only applies to Atlassian products on the Data Center platform.

Note that this KB was created for the Data Center version of the product. Data Center KBs for non-Data-Center-specific features may also work for Server versions of the product, however they have not been tested. Support for Server* products ended on February 15th 2024. If you are running a Server product, you can visit the Atlassian Server end of support announcement to review your migration options.

*Except Fisheye and Crucible

Summary

The Jira performance log atlassian-jira-perf.log contains valuable information logged every minute with Jira application utilizing jmx to expose run time metrics such as

  • JMXINSTRUMENTS-OS - Contains information on OS related metrics such as swap memory usage, system load average, virtual memory size etc.
  • JMXINSTRUMENTS-GC - Garbage collection count and collection time in young generation and old generation of the heap.
  • JMXINSTRUMENTS-Threading - Total thread count, peak thread count, daemon thread count
  • JMXINSTRUMENTS-ThreadPool - Information on busy threads, max threads etc. which can be used decide when to get thread dumps.
  • PLATFORMINSTRUMENTS - Loads of metrics, about dbcp pool, thread count, memory usage, issue created count, velocity template exception etc.

Firstly, you can gather information about all the metrics that are printed out by each of the instrumentation above with a command like below. You would want to install json parser jq . The output would look like below. This is to help identify and gather and plot metrics that may not be analyzed or plotted in the tools you might be currently using for troubleshooting.

% cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-OS/{$1="";$2="";$3="";print}' | jq -s '.[1] | .[].attributes[].name'
"OpenFileDescriptorCount"
"MaxFileDescriptorCount"
"CommittedVirtualMemorySize"
"TotalSwapSpaceSize"
"FreeSwapSpaceSize"
"ProcessCpuTime"
"FreePhysicalMemorySize"
"TotalPhysicalMemorySize"
"SystemCpuLoad"
"ProcessCpuLoad"
"SystemLoadAverage"
"AvailableProcessors"

% cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-GC/{$1="";$2="";$3="";print}' | jq -s '.[1] | .[].attributes[].name'
"CollectionCount"
"CollectionTime"
"Name"
"CollectionCount"
"CollectionTime"
"Name"

% cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-Threading/{$1="";$2="";$3="";print}' | jq -s '.[1] | .[].attributes[].name'
"CurrentThreadUserTime"
"ThreadCount"
"TotalStartedThreadCount"
"CurrentThreadCpuTime"
"PeakThreadCount"
"DaemonThreadCount"

% cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-ThreadPool/{$1="";$2="";$3="";print}' | jq -s '.[1] | .[].ObjectName' 
"Catalina:name=\"https-jsse-nio-8080\",type=ThreadPool"
"Catalina:name=\"http-nio-8898\",type=ThreadPool"
 
% cat atlassian-jira-perf.log | awk '/PLATFORMINSTRUMENTS/{$1="";$2="";$3="";print}' | jq -s '.[1] |.instrumentList[].name' | sed -e 's/,//g' -e 's/"//g' | awk -v ORS="\n" '{print}' | sort cache.JiraOsgiContainerManager.evictionCount
cache.JiraOsgiContainerManager.hitCount
cache.JiraOsgiContainerManager.loadExceptionCount
cache.JiraOsgiContainerManager.loadSuccessCount
cache.JiraOsgiContainerManager.missCount
cache.JiraOsgiContainerManager.size
cache.JiraOsgiContainerManager.totalLoadTime
cache.VelocityTemplateCache.directives.evictionCount
cache.VelocityTemplateCache.directives.hitCount
cache.VelocityTemplateCache.directives.loadExceptionCount
cache.VelocityTemplateCache.directives.loadSuccessCount
cache.VelocityTemplateCache.directives.missCount
cache.VelocityTemplateCache.directives.size
cache.VelocityTemplateCache.directives.totalLoadTime
cache.VelocityTemplateCache.evictionCount
cache.VelocityTemplateCache.hitCount
cache.VelocityTemplateCache.loadExceptionCount
cache.VelocityTemplateCache.loadSuccessCount
cache.VelocityTemplateCache.missCount
cache.VelocityTemplateCache.size
cache.VelocityTemplateCache.totalLoadTime
cache.i18n.CachingI18nFactory.evictionCount
cache.i18n.CachingI18nFactory.hitCount
cache.i18n.CachingI18nFactory.loadExceptionCount
cache.i18n.CachingI18nFactory.loadSuccessCount
cache.i18n.CachingI18nFactory.missCount
cache.i18n.CachingI18nFactory.size
cache.i18n.CachingI18nFactory.totalLoadTime
concurrent.requests
dashboard.view.count
db.conns
db.conns.borrowed
db.conns.time.to.borrow
db.reads
db.writes
dbcp.maxActive
dbcp.numActive
dbcp.numIdle
entity.attachments.total
entity.components.total
entity.customfields.total
entity.filters.total
entity.groups.total
entity.issues.total
entity.projects.total
entity.users.total
entity.versions.total
entity.workflows.total
five.hundreds
http.session.objects
http.sessions
index.writes
issue.assigned.count
issue.created.count
issue.index.reads
issue.link.count
issue.search.count
issue.updated.count
issue.worklogged.count
jira.license
jmx.class.loaded.current
jmx.class.loaded.total
jmx.class.unloaded.total
jmx.gc
jmx.memory.heap.committed
jmx.memory.heap.used
jmx.memory.nonheap.committed
jmx.memory.nonheap.used
jmx.system.up.time
jmx.thread.cpu.block.count
jmx.thread.cpu.block.time
jmx.thread.cpu.time
jmx.thread.cpu.user.time
jmx.thread.cpu.wait.count
jmx.thread.cpu.wait.time
jmx.thread.daemon.count
jmx.thread.ever.count
jmx.thread.nondaemon.count
jmx.thread.peak.count
jmx.thread.total.count
quicksearch.concurrent.search
sd.automation.async.psmq.thread.active.size
sd.automation.async.psmq.thread.pool.size
sd.automation.async.psmq.wait.queue.depth
sd.automation.async.then.psmq.thread.active.size
sd.automation.async.then.psmq.thread.pool.size
sd.automation.async.then.psmq.wait.queue.depth
web.requests
writer.lucene.commit

Environment

9.x

Solution

For the PLATFORMINSTRUMENTS, which has too many metrics, it can be configured to print out the name and value for only certain metrics by providing a regex pattern. Below the Parameter variable can be modified to print only the metrics that match a pattern. You can also try a pattern such as "entity.*count" , "cache.*" , "dbcp.*" or even full metric name such as "web.requests" substituting in the parameter variable. Below we would be printing all metrics related to issues by using "issue.*count" as parameter.

parameter="issue.*count";ParseVar=$(cat atlassian-jira-perf.log | awk '/PLATFORMINSTRUMENTS/{$1="";$2="";$3="";print}' | jq --arg param $parameter -s '.|.[1] |.instrumentList[]|select(.name|test($param)).name' | sed -e 's/,//g' -e 's/"//g' | awk -v ORS=" " '{print}'); PrintVar=$(eval echo $ParseVar); cat atlassian-jira-perf.log | awk '/PLATFORMINSTRUMENTS/{$1="";$2="";$3="";print}' | jq --arg param $parameter -r '.|[.timestamp,(.instrumentList[]|select(.name|test($param))|.value)] | @tsv'| gawk -v var="$PrintVar" 'BEGIN {print "timestamp",var}{print strftime("%Y-%m-%d-%H:%M:%S",$1), $1="",$0}' | column -t

timestamp            issue.link.count  issue.created.count  issue.search.count  issue.updated.count  issue.assigned.count  issue.worklogged.count
2023-02-26-20:37:08  64                33                   0                   135                  9                     5
2023-02-26-20:38:07  64                33                   0                   135                  9                     5
2023-02-26-20:39:07  64                33                   0                   135                  9                     5
2023-02-26-20:40:07  64                33                   0                   135                  9                     5
2023-02-26-20:41:07  64                33                   0                   135                  9                     5
2023-02-26-20:42:07  64                33                   0                   135                  9                     5
2023-02-26-20:43:07  64                33                   0                   135                  9                     5
2023-02-26-20:44:07  64                33                   0                   137                  9                     5
2023-02-26-20:45:07  64                33                   0                   137                  9                     5
2023-02-26-20:46:07  64                33                   0                   138                  9                     5
2023-02-26-20:47:07  64                33                   0                   138                  9                     5
2023-02-26-20:48:08  64                33                   0                   138                  9                     5
..................

The metrics for JMXINSTRUMENTS-GC and JMXINSTRUMENTS-Threading and JMXINSTRUMENTS-ThreadPool are few and can be printed in whole by running the below commands.

JMXINSTRUMENTS-GC

ParseVar=$(cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-GC /{$1="";$2="";$3="";print}' | jq -s '.[1] | .[0].attributes[2].name,.[0].attributes[0].name,.[0].attributes[1].name,.[1].attributes[2].name,.[1].attributes[0].name,.[1].attributes[1].name' | sed -e 's/,//g' -e 's/"//g' | awk -v ORS=" " '{print}'); PrintVar=$(eval echo $ParseVar); cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-GC /{$1="";$2="";$3="";print}' | jq -r '.[]|[.timestamp,(.attributes[2].value),(.attributes[0].value),(.attributes[1].value)] | @tsv' | awk '{key1=sprintf("%s%s%s%s",$1" ",$2$3$4" ",$5" ",$6);getline;key2=sprintf("%s%s%s",$2$3$4" ",$5" ",$6);print key1,key2}' | gawk -v var="$PrintVar" 'BEGIN {print "timestamp",var}{print strftime("%Y-%m-%d-%H:%M:%S",$1),$1="",$0}' | column -t

timestamp            Name               CollectionCount  CollectionTime  Name             CollectionCount  CollectionTime
2023-02-26-20:36:07  G1YoungGeneration  364              53671           G1OldGeneration  0                0
2023-02-26-20:37:07  G1YoungGeneration  366              54004           G1OldGeneration  0                0
2023-02-26-20:38:07  G1YoungGeneration  367              54212           G1OldGeneration  0                0
2023-02-26-20:39:07  G1YoungGeneration  368              54343           G1OldGeneration  0                0
2023-02-26-20:40:07  G1YoungGeneration  370              54697           G1OldGeneration  0                0
2023-02-26-20:41:07  G1YoungGeneration  371              54950           G1OldGeneration  0                0
2023-02-26-20:42:07  G1YoungGeneration  373              55198           G1OldGeneration  0                0
2023-02-26-20:43:07  G1YoungGeneration  376              55696           G1OldGeneration  0                0
2023-02-26-20:44:07  G1YoungGeneration  377              55795           G1OldGeneration  0                0
2023-02-26-20:45:07  G1YoungGeneration  378              55875           G1OldGeneration  0                0
2023-02-26-20:46:07  G1YoungGeneration  379              55952           G1OldGeneration  0                0
2023-02-26-20:47:07  G1YoungGeneration  380              56017           G1OldGeneration  0                0
..................

JMXINSTRUMENTS-Threading

ParseVar=$(cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-Threading/{$1="";$2="";$3="";print}' | jq -s '.[1] | .[].attributes[].name' | sed -e 's/,//g' -e 's/"//g' | awk -v ORS=" " '{print}');PrintVar=$(eval echo $ParseVar); cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-Threading/{$1="";$2="";$3="";print}' | jq -r '.[]|[.timestamp,(.attributes[].value)] | @tsv' | gawk -v var="$PrintVar" 'BEGIN {print "timestamp",var}{print strftime("%Y-%m-%d-%H:%M:%S",$1),$1="",$0}' | column -t

timestamp            CurrentThreadUserTime  ThreadCount  TotalStartedThreadCount  CurrentThreadCpuTime  PeakThreadCount  DaemonThreadCount
2023-02-26-20:36:07  1270000000             482          3249                     2600797393            516              435
2023-02-26-20:37:07  1270000000             481          3254                     2605854808            516              436
2023-02-26-20:38:07  1270000000             482          3258                     2611078087            516              435
2023-02-26-20:39:07  1270000000             482          3262                     2616168067            516              436
2023-02-26-20:40:07  1280000000             481          3265                     2621064992            516              435
2023-02-26-20:41:07  1280000000             480          3267                     2625968279            516              435
2023-02-26-20:42:07  1280000000             481          3271                     2630787881            516              435
2023-02-26-20:43:07  1280000000             480          3278                     2635774761            516              435
...................

JMXINSTRUMENTS-ThreadPool

ParseVar=$(cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-ThreadPool/{$1="";$2="";$3="";print}' | jq -s '.[1] | [.[].ObjectName] | @csv' | sed -e 's/Catalina:name=//g' -e 's/type=ThreadPool//g' -e 's/"//g' -e 's/\\//g' -e 's/,/ /g');PrintVar=$(eval echo $ParseVar); cat atlassian-jira-perf.log*  | awk '/JMXINSTRUMENTS-ThreadPool/{$1="";$2="";$3="";print}' | jq -r '. | .[0].timestamp as $time | [$time, (.[].attributes[]|select(.name|contains("currentThreadsBusy"))|.value)]| @tsv' | gawk -v var="$PrintVar" 'BEGIN {print "timestamp",var}{print strftime("%Y-%m-%d-%H:%M:%S",$1), $1="",$0}' | column -t

timestamp            https-jsse-nio-8080  http-nio-8898
2023-03-27-10:31:49  3                    30
2023-03-27-10:32:49  3                    20
2023-03-27-10:33:49  4                    25
2023-03-27-10:34:49  4                    35
2023-03-27-10:35:49  5                    45
2023-03-27-10:36:49  6                    55
2023-03-27-10:37:49  6                    50
....................

Similar to PLATFORMINSTRUMENTS, the JMXINSTRUMENTS-OS can also be parameterized to provide only certain metrics such as SystemLoadAverage, ProcessCpuLoad, OpenFileDescriptorCount etc. Here we parameterize for physicalmemory

parameter=".*PhysicalMemory.*";ParseVar=$(cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-OS/{$1="";$2="";$3="";print}' | jq --arg param $parameter -s '.[1] | .[].attributes[]|select(.name|test($param)).name' | sed -e 's/,//g' -e 's/"//g' | awk -v ORS=" " '{print}');PrintVar=$(eval echo $ParseVar); cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-OS/{$1="";$2="";$3="";print}' | jq --arg param $parameter -r '.[]|[.timestamp,(.attributes[]|select(.name|test($param))|.value)] | @tsv' | gawk -v var="$PrintVar" 'BEGIN {print "timestamp",var}{print strftime("%Y-%m-%d-%H:%M:%S",$1),$1="",$0}' | column -t

timestamp            FreePhysicalMemorySize  TotalPhysicalMemorySize
2023-02-26-20:36:07  4483416064              101206396928
2023-02-26-20:37:07  4480978944              101206396928
2023-02-26-20:38:07  4491440128              101206396928
2023-02-26-20:39:07  4497281024              101206396928
2023-02-26-20:40:07  4477222912              101206396928
2023-02-26-20:41:07  4473540608              101206396928
2023-02-26-20:42:07  4468113408              101206396928
.........

The non-parameterized version of the script for gathering all the metrics for JMXINSTRUMENTS-OS is provided below

ParseVar=$(cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-OS/{$1="";$2="";$3="";print}' | jq -s '.[1] | .[].attributes[].name' | sed -e 's/,//g' -e 's/"//g' | awk -v ORS=" " '{print}');PrintVar=$(eval echo $ParseVar); cat atlassian-jira-perf.log | awk '/JMXINSTRUMENTS-OS/{$1="";$2="";$3="";print}' | jq -r '.[]|[.timestamp,(.attributes[].value)] | @tsv' | gawk -v var="$PrintVar" 'BEGIN {print "timestamp",var}{print strftime("%Y-%m-%d-%H:%M:%S",$1),$1="",$0}' | column -t



Last modified on Mar 30, 2023

Was this helpful?

Yes
No
Provide feedback about this article

Related content

  • No related content found
Powered by Confluence and Scroll Viewport.