Indexing Stats - cost of indexing custom fields
Platform notice: Server and Data Center only. This article only applies to Atlassian products on the Server and Data Center platforms.
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
(The indexing-stats log presented on this page is available for Jira 8.1 and later.)
The most expensive part of indexing is creating a Lucene Document to be indexed.
Here are the logs that can help in determining which field indexers are the "most expensive" (in time) and how they affect the overall indexing time.
Periodic Stats
These indexing stats are logged every 5mins. During the full foreground reindex they will relate only to the foreground indexing. During normal Jira operation this will be the measuring "normal" indexing tasks, caused by user actions or any other indexing action (like background indexing, de-archiving, and the like).
[indexing-stats] Top 10 addIndex total (noFieldIndexers: 68, sum: 10203600ms): [
{field: customfield_10000 (Approvals),
addIndex: {sum/allSum:21.1%, sum:2151531ms, avg:7.8ms, max:2750ms, count:274370}},
{field: customfield_10304 (Change reason),
addIndex: {sum/allSum:15.8%, sum:1613150ms, avg:5.9ms, max:812ms, count:274379}},
{field: issuelinks,
addIndex: {sum/allSum:9.9%, sum:1005236ms, avg:3.7ms, max:809ms, count:274374}},
...]
[indexing-stats] Top 10 addIndex snapshot (noFieldIndexers: 68, sum: 3427078ms) ...- Top 10 addIndex total - top most expensive indexing fields “forever”; “total” is “forever”, which means since this Jira started or since the start of the last re-index.
- Top 10 addIndex snapshot - top most expensive indexing fields in the last few minutes; “snapshot” means these are stats since the last snapshot (5min)
- (noFieldIndexers: 68, sum: 10203600ms) - number of field indexers and total sum of all indexers
- field: customfield_10000 (Approvals): - identifiable field name
- addIndex: sum/allSum - time spent on this field vs all fields
- addIndex: sum,avg,max - sum / avg / max time spend on this field
- addIndex: count - number of calls
After Re-index stats
These are indexing stats presented after a full foreground re-index finished. They are the most accurate as during this time Jira is not doing anything else and present the cost of all field indexers and how they affected the overall indexing time.
[indexing-stats] field indexing cost:
{order:1,
name:customfield_10000 (Approvals),
isKnown:false,
addIndex: {sum:2328373ms, avg:7.7ms, max:2750ms, count:302109},
totalIndexTime:984864ms,
addIndexSum/totalIndexTime:236.4%,
numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:2,...
...
[indexing-stats] field indexing cost: {order:68,...This log shows you the cost of all field indexers (order by the cost DESC).
- order - 1 most expensive
- name:customfield_10000 (Approvals) - field name
- isKnown:false - if true this is a system custom field (Jira Core internal)
- addIndex sum / avg / max / count - cost as in previous log message
- totalIndexTime - total re-indexing time
- addIndexSum/totalIndexTime - cost (in time) of getting this field vs total re-index time; because we have many indexing threads this can be more than 100%
- numberOfIndexingThreads - number of indexing threads (mentioned in the previous metric)
Example
Example data from Jira Service Management 4.0 with Jira 8.1 with 300k issues.
Periodic logs
[indexing-stats] Top 10 addIndex total (noFieldIndexers: 66, sum: 32140610ms): [
{field: customfield_10201 (Time to resolution), addIndex: {sum/allSum:11.2%, sum:3595247ms, avg:12.3ms, max:2555ms, count:291614}},
{field: customfield_10202 (Time to first response), addIndex: {sum/allSum:10.7%, sum:3443150ms, avg:11.8ms, max:1403ms, count:291609}},
{field: customfield_10401 (Custom2), addIndex: {sum/allSum:5.4%, sum:1736124ms, avg:6.0ms, max:1402ms, count:291606}},
{field: customfield_10404 (Custom5), addIndex: {sum/allSum:5.3%, sum:1702518ms, avg:5.8ms, max:1403ms, count:291605}},
{field: customfield_10317 (Time to approve normal change), addIndex: {sum/allSum:5.3%, sum:1688969ms, avg:5.8ms, max:969ms, count:291613}},
{field: customfield_10402 (Custom3), addIndex: {sum/allSum:5.2%, sum:1659112ms, avg:5.7ms, max:1400ms, count:291599}},
{field: customfield_10406 (Custom7), addIndex: {sum/allSum:5.2%, sum:1655281ms, avg:5.7ms, max:222ms, count:291606}},
{field: customfield_10400 (Custom1), addIndex: {sum/allSum:5.1%, sum:1652856ms, avg:5.7ms, max:1400ms, count:291612}},
{field: customfield_10316 (Time to close after resolution), addIndex: {sum/allSum:5.1%, sum:1648315ms, avg:5.7ms, max:1403ms, count:291606}},
{field: customfield_10405 (Custom6), addIndex: {sum/allSum:5.1%, sum:1633478ms, avg:5.6ms, max:218ms, count:291604}}]
[indexing-stats] Top 10 addIndex snapshot (noFieldIndexers: 66, sum: 4756291ms): [
{field: customfield_10201 (Time to resolution), addIndex: {sum/allSum:11.3%, sum:536496ms, avg:12.4ms, max:228ms, count:43370}},
{field: customfield_10202 (Time to first response), addIndex: {sum/allSum:10.8%, sum:512125ms, avg:11.8ms, max:221ms, count:43372}},
{field: customfield_10401 (Custom2), addIndex: {sum/allSum:5.4%, sum:258216ms, avg:6.0ms, max:208ms, count:43371}},
{field: customfield_10317 (Time to approve normal change), addIndex: {sum/allSum:5.3%, sum:253002ms, avg:5.8ms, max:210ms, count:43370}},
{field: customfield_10400 (Custom1), addIndex: {sum/allSum:5.2%, sum:245748ms, avg:5.7ms, max:209ms, count:43371}},
{field: customfield_10316 (Time to close after resolution), addIndex: {sum/allSum:5.1%, sum:244812ms, avg:5.6ms, max:207ms, count:43372}},
{field: customfield_10406 (Custom7), addIndex: {sum/allSum:5.1%, sum:243580ms, avg:5.6ms, max:206ms, count:43369}},
{field: customfield_10404 (Custom5), addIndex: {sum/allSum:5.1%, sum:243121ms, avg:5.6ms, max:214ms, count:43373}},
{field: customfield_10402 (Custom3), addIndex: {sum/allSum:5.1%, sum:242026ms, avg:5.6ms, max:216ms, count:43369}},
{field: customfield_10403 (Custom4), addIndex: {sum/allSum:5.1%, sum:241619ms, avg:5.6ms, max:217ms, count:43372}}]
After re-index logs
ReindexAll took: 2203668 ms in foreground
[indexing-stats] field indexing cost: {order:1, name:customfield_10202 (Time to first response), isKnown:false, addIndex: {sum:3554163ms, avg:11.8ms, max:1468ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:161.3%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:2, name:customfield_10201 (Time to resolution), isKnown:false, addIndex: {sum:3500704ms, avg:11.6ms, max:1458ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:158.9%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:3, name:customfield_10000 (Approvals), isKnown:false, addIndex: {sum:2410210ms, avg:8.0ms, max:1456ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:109.4%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:4, name:customfield_10404 (Custom5), isKnown:false, addIndex: {sum:1745079ms, avg:5.8ms, max:1456ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:79.2%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:5, name:customfield_10317 (Time to approve normal change), isKnown:false, addIndex: {sum:1740746ms, avg:5.8ms, max:1456ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:79.0%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:6, name:customfield_10401 (Custom2), isKnown:false, addIndex: {sum:1709668ms, avg:5.7ms, max:218ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:77.6%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:7, name:customfield_10400 (Custom1), isKnown:false, addIndex: {sum:1705397ms, avg:5.6ms, max:1460ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:77.4%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:8, name:customfield_10402 (Custom3), isKnown:false, addIndex: {sum:1704191ms, avg:5.6ms, max:215ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:77.3%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:9, name:customfield_10406 (Custom7), isKnown:false, addIndex: {sum:1703002ms, avg:5.6ms, max:1458ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:77.3%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:10, name:customfield_10316 (Time to close after resolution), isKnown:false, addIndex: {sum:1694045ms, avg:5.6ms, max:214ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:76.9%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:11, name:customfield_10407 (Custom8), isKnown:false, addIndex: {sum:1689112ms, avg:5.6ms, max:1456ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:76.7%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:12, name:customfield_10405 (Custom6), isKnown:false, addIndex: {sum:1684330ms, avg:5.6ms, max:1457ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:76.4%, numberOfIndexingThreads:20}
[indexing-stats] field indexing cost: {order:13, name:customfield_10403 (Custom4), isKnown:false, addIndex: {sum:1682427ms, avg:5.6ms, max:257ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:76.3%, numberOfIndexingThreads:20}
...
[indexing-stats] field indexing cost: {order:68, name:workratio, isKnown:false, addIndex: {sum:140ms, avg:0.0ms, max:2ms, count:302109}, totalIndexTime:2203668ms, addIndexSum/totalIndexTime:0.0%, numberOfIndexingThreads:20}
Reindex took: 2203668ms. Indexer: DefaultIndexManager: paths: [/home/ubuntu/jirahome/caches/indexesV1/comments, /home/ubuntu/jirahome/caches/indexesV1/issues, /home/ubuntu/jirahome/caches/indexesV1/changes, /home/ubuntu/jirahome/caches/indexesV1/worklogs, /home/ubuntu/jirahome/caches/indexesV1/plugins/servicedeskcannedresponses]In this case the full re-index took: 2203668 ms in foreground, which is 37min.
Let’s look at the most expensive indexing field:
Order 1
The first one on the list is customfield_10202 (Time to first response) took 3554163ms, which is 59min. Remember that to increase the performance of loading the data we have multiple indexing threads: numberOfIndexingThreads:20.
[indexing-stats] field indexing cost: {order:1, name:customfield_10202 (Time to first response), isKnown:false,
addIndex: {sum:3554163ms, avg:11.8ms, max:1468ms, count:302109},
totalIndexTime:2203668ms, addIndexSum/totalIndexTime:161.3%, numberOfIndexingThreads:20}Order 2
The second one on the list is customfield_10201 (Time to resolution) that took 3500704ms, which is 58min.
[indexing-stats] field indexing cost: {order:2, name:customfield_10201 (Time to resolution), isKnown:false,
addIndex: {sum:3500704ms, avg:11.6ms, max:1458ms, count:302109},
totalIndexTime:2203668ms, addIndexSum/totalIndexTime:158.9%, numberOfIndexingThreads:20}Order 3
The 3rd on the list is customfield_10000 (Approvals) with 2410210ms, which is 40min.
[indexing-stats] field indexing cost: {order:3, name:customfield_10000 (Approvals), isKnown:false,
addIndex: {sum:2410210ms, avg:8.0ms, max:1456ms, count:302109},
totalIndexTime:2203668ms, addIndexSum/totalIndexTime:109.4%, numberOfIndexingThreads:20}So getting data for those 3 custom fields took 161% + 158% + 109% = 428% of indexing time, so more than 4 out of 20 indexing threads would be used just to load data for those 3 fields.
Resolution
Please review the top 3 custom field contexts above to validate if there's any field using global field context. A custom field using a global context would cause some expensive indexing time. It would be great to limit the availability of a custom field to specific projects that will actually use it. Large numbers of custom fields with global contexts have a significant impact on system performance.
- Optimizing Custom Fields (only available in DC version)