Indexing Stats - cost of indexing custom fields

お困りですか?

アトラシアン コミュニティをご利用ください。

コミュニティに質問

(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 background 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 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:

[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}

Getting data for name: 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.

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}


The 3rd on the list is customfield_10000 (Approvals) with 2410210ms,  which is 40min.

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.


最終更新日 2020 年 11 月 23 日

この内容はお役に立ちましたか?

はい
いいえ
この記事についてのフィードバックを送信する
Powered by Confluence and Scroll Viewport.