nav[aria-label="Primary Navigation"] { padding: 0; & ul { list-style: none; width: 100%; display: flex; flex-direction: row; justify-content: start; align-items: start; gap: 30px; padding: 0; & li { margin: 0; } & ul li { list-style: none; } } }

What are the fields in slow queries log?

Seb Kouba1

I would like to know what the different elements in the slow queries log file represent. I think I've figure out most but I don't know where to look it up since it doesn't seem to be part of any config I could find.

Any suggestions?

I figured the following...

2016-11-21 09:08:49,068
http-nio-8080-exec-16 INFO username 548x103721x5 11nnyad /url/ [issue.search.providers.LuceneSearchProvider_SLOW] JQL query '{filter in ("Release actual ")} ' produced lucene query redacted_query' and took '561' ms to run.


Timestamp thread? type? Username log_id ??? url query_info query duration

Accepted answers

crf

Basics

2016-11-21 09:08:49,068 – Timestamp
http-nio-8080-exec-16 – Thread
INFO – Log level
username – Well, yes
548x103721x5 – jira.request.id (see below)
11nnyad – <code>jira.request.assession.id (see below)
/url/ – Well, yes
[issue.search.providers.LuceneSearchProvider_SLOW] – logger name
Next comes the log message with the fields:
- '{filter in ("Release actual ")}' – the JQL
- redacted_query – the resulting Lucene search expression (warning: may contain binary data if that's the form that the data takes in the index)
- '561' ms – how long it took (we log anything over 400ms by default)

About `jira.request.id`

This is meant to be a unique identifier for each HTTP request so you can filter by it to group together all the log messages that are tied to it. You could just treat it as an opaque string, but if you're curious, it consists of 3 numbers with the following meaning:

The first number (548) is roughly the time of day, in minutes since midnight. Internal comments in the code still match the ancient versions of JIRA (prior to 4.1) when it was seconds since midnight so could be as large as 86400 or so, but since JIRA 4.1 it should stay under 1440.
The second number (103721) is a cumulative request counter. It increments with every request and should therefore guarantee that the overall request ID is always unique (the other fields are there to give other information). Well, except that this counter resets if you restart JIRA. This is part of why the first number, giving time of day, is also included.
The third number (5) is the number of concurrent HTTP requests that were being processed at the time the ID was generated (it is not updated if the count changes within the request, but offers some idea of how busy the system might have been at the time, which sometimes matters).

About `jira.request.assession.id`

This is the HTTP session ID, but hashed so that it cannot be abused to steal a user's session and impersonate them. The intent is that if a user is complaining that something is wrong and you can get them to tell you the value of the ASESSIONID cookie that their browser has for that JIRA instance, this gives you a way to correlate that specific session's activity instead of all activity for that user. This would be particularly important when trying to troubleshoot something that happens to the user in one login session but not on another machine or has correctly entered their password but still gets sent back to the login page for some reason.

All comments

crf

Basics

2016-11-21 09:08:49,068 – Timestamp
http-nio-8080-exec-16 – Thread
INFO – Log level
username – Well, yes
548x103721x5 – jira.request.id (see below)
11nnyad – <code>jira.request.assession.id (see below)
/url/ – Well, yes
[issue.search.providers.LuceneSearchProvider_SLOW] – logger name
Next comes the log message with the fields:
- '{filter in ("Release actual ")}' – the JQL
- redacted_query – the resulting Lucene search expression (warning: may contain binary data if that's the form that the data takes in the index)
- '561' ms – how long it took (we log anything over 400ms by default)

About `jira.request.id`

The first number (548) is roughly the time of day, in minutes since midnight. Internal comments in the code still match the ancient versions of JIRA (prior to 4.1) when it was seconds since midnight so could be as large as 86400 or so, but since JIRA 4.1 it should stay under 1440.
The second number (103721) is a cumulative request counter. It increments with every request and should therefore guarantee that the overall request ID is always unique (the other fields are there to give other information). Well, except that this counter resets if you restart JIRA. This is part of why the first number, giving time of day, is also included.
The third number (5) is the number of concurrent HTTP requests that were being processed at the time the ID was generated (it is not updated if the count changes within the request, but offers some idea of how busy the system might have been at the time, which sometimes matters).

About `jira.request.assession.id`

Seb Kouba1

Thanks for this detailed answer. I really appreciate it.

In case anybody finds this. I was playing with Splunk and it seems that not all elements are present for every line in the log so watch out for that...

crf

See what I said about "redacted_query" above.

warning: may contain binary data if that's the form that the data takes in the index

These are the raw binary values that are stored for these fields in the index, and they are very likely to confuse the character encoding for something like JSON or XML. I'm not overly familiar with Splunk, but I'm given to understand that it uses JSON as its transport. It will expect the log message to be well-formed UTF-8, and it isn't.

Seb Kouba1

That wasn't the part that was messing with the extraction. There was a string I could use to identify the end of the Leucene search expression. I can't seem to access the regexp that I was using to extract the data from Splunk, which sucks...

Welcome!

It looks like you're new here. Sign in or register to get started.

Quick Links

Find more posts tagged with

jira

jira-core