Search profiling for fetch phases

[nik9000]

I was helping some folks to debug a thing this morning and we had questions about the fetch performance and I was sad that we didn't profile the fetch phase. And I realized I had the same issue a week ago when I was helping some other folks. And I'd had the issue many more times before that.

Do folks think it'd be worth profiling the fetch phase?

I know a big chunk of the fetch phase is spent loading stored fields needed by the other phases. But I don't know how much of the time is that vs time spent chewing on the data or on docvalue_fields or whatever.

[elasticmachine]

Pinging @elastic/es-search (Team:Search)

[nik9000]

I've been working on prototypes for other things for so long I needed to take some time to do something "contained" so I made a prototype:

      {
        "id" : "[1uXDrrPjSfu7W0KA-703jQ][test][2]",
        "searches" : [ ... ],
        "aggregations" : [ ],
        "fetch" : {
          "type" : "fetch",
          "description" : "fetch",
          "time_in_nanos" : 5268936,
          "breakdown" : {
            "load_stored_fields" : 2893202,
            "load_stored_fields_count" : 357,
            "next_reader" : 20702,
            "next_reader_count" : 1
          },
          "debug" : {
            "stored_fields" : [
              "_id",
              "_routing",
              "_source"
            ]
          },
          "children" : [
            {
              "type" : "doc_values",
              "description" : "fetches doc_values",
              "time_in_nanos" : 221701,
              "breakdown" : {
                "process_count" : 357,
                "process" : 211053,
                "next_reader" : 10648,
                "next_reader_count" : 1
              }
            },
            {
              "type" : "source",
              "description" : "load _source",
              "time_in_nanos" : 484075,
              "breakdown" : {
                "process_count" : 357,
                "process" : 483912,
                "next_reader" : 163,
                "next_reader_count" : 1
              }
            }
          ]
        }
      }

[jpountz]

Do folks think it'd be worth profiling the fetch phase?

Totally. I think that the only reason why it's not done today is that the query phase is a more common bottleneck, but I remember seeing cases in the past when the fetch phase was a bottleneck too, so +1 to add profiling to the fetch phase.

[nik9000]

Cool. I have a prototype. I hope to have a PR today.

…

On Tue, Aug 31, 2021, 06:04 Adrien Grand ***@***.***> wrote: Do folks think it'd be worth profiling the fetch phase? Totally. I think that the only reason why it's not done today is that the query phase is a more common bottleneck, but I remember seeing cases in the past when the fetch phase was a bottleneck too, so +1 to add profiling to the fetch phase. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#75892 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABUXIWVKLG56SNWXGUYBR3T7SSLHANCNFSM5BIR2NEQ> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.