Magesh Narayanan
Magesh Narayanan

Reputation: 155

Chrome Developer Tools - Performance profiling

In the below image (from chrome performance profiling tab for a API call), what is resource loading which costs 719 ms ?

If I visit the network tab, for the same API call, I see only 10.05 seconds.

What is resource loading mean here ? Is there any specific activity the browser does after receiving the data ?

enter image description here

Upvotes: 12

Views: 2901

Answers (1)

THE AMAZING
THE AMAZING

Reputation: 1603

As @wOxxOM stated, buildNetworkRequestDetails is being called from Source Code

From the statement by @Sanju singh :

that statement doesn't tell anything, why it is taking that much time to make the resource available?

I think its necessary to break down exactly what is happening.. Summary: Activity Browser and Network Activity are using different algorithms for calculating completion. Network Activity is calculating the response times from the request and Activity Browser is calculating the response time + time it took to add it into the WebInspector tracer.

Looking at

/**
   * @param {!TimelineModel.TimelineModel.NetworkRequest} request
   * @param {!TimelineModel.TimelineModel.TimelineModelImpl} model
   * @param {!Components.Linkifier.Linkifier} linkifier
   * @return {!Promise<!DocumentFragment>}
   */
  static async buildNetworkRequestDetails(request, model, linkifier) {
    const target = model.targetByEvent(request.children[0]);
    const contentHelper = new TimelineDetailsContentHelper(target, linkifier);
    const category = TimelineUIUtils.networkRequestCategory(request);
    const color = TimelineUIUtils.networkCategoryColor(category);
    contentHelper.addSection(ls`Network request`, color);

    if (request.url) {
      contentHelper.appendElementRow(ls`URL`, Components.Linkifier.Linkifier.linkifyURL(request.url));
    }

    // The time from queueing the request until resource processing is finished.
    const fullDuration = request.endTime - (request.getStartTime() || -Infinity);
    if (isFinite(fullDuration)) {
      let textRow = Number.millisToString(fullDuration, true);
      // The time from queueing the request until the download is finished. This
      // corresponds to the total time reported for the request in the network tab.
      const networkDuration = request.finishTime - request.getStartTime();
      // The time it takes to make the resource available to the renderer process.
      const processingDuration = request.endTime - request.finishTime;
      if (isFinite(networkDuration) && isFinite(processingDuration)) {
        const networkDurationStr = Number.millisToString(networkDuration, true);
        const processingDurationStr = Number.millisToString(processingDuration, true);
        const cacheOrNetworkLabel = request.cached() ? ls`load from cache` : ls`network transfer`;
        textRow += ls` (${networkDurationStr} ${cacheOrNetworkLabel} + ${processingDurationStr} resource loading)`;
      }
      contentHelper.appendTextRow(ls`Duration`, textRow);
    }

    if (request.requestMethod) {
      contentHelper.appendTextRow(ls`Request Method`, request.requestMethod);
    }
    if (typeof request.priority === 'string') {
      const priority = PerfUI.NetworkPriorities.uiLabelForNetworkPriority(
          /** @type {!Protocol.Network.ResourcePriority} */ (request.priority));
      contentHelper.appendTextRow(ls`Priority`, priority);
    }
    if (request.mimeType) {
      contentHelper.appendTextRow(ls`Mime Type`, request.mimeType);
    }
    let lengthText = '';
    if (request.memoryCached()) {
      lengthText += ls` (from memory cache)`;
    } else if (request.cached()) {
      lengthText += ls` (from cache)`;
    } else if (request.timing && request.timing.pushStart) {
      lengthText += ls` (from push)`;
    }
    if (request.fromServiceWorker) {
      lengthText += ls` (from service worker)`;
    }
    if (request.encodedDataLength || !lengthText) {
      lengthText = `${Number.bytesToString(request.encodedDataLength)}${lengthText}`;
    }
    contentHelper.appendTextRow(ls`Encoded Data`, lengthText);
    if (request.decodedBodyLength) {
      contentHelper.appendTextRow(ls`Decoded Body`, Number.bytesToString(request.decodedBodyLength));
    }
    const title = ls`Initiator`;
    const sendRequest = request.children[0];
    const topFrame = TimelineModel.TimelineModel.TimelineData.forEvent(sendRequest).topFrame();
    if (topFrame) {
      const link = linkifier.maybeLinkifyConsoleCallFrame(target, topFrame, {tabStop: true});
      if (link) {
        contentHelper.appendElementRow(title, link);
      }
    } else {
      const initiator = TimelineModel.TimelineModel.TimelineData.forEvent(sendRequest).initiator();
      if (initiator) {
        const initiatorURL = TimelineModel.TimelineModel.TimelineData.forEvent(initiator).url;
        if (initiatorURL) {
          const link = linkifier.maybeLinkifyScriptLocation(target, null, initiatorURL, 0, {tabStop: true});
          if (link) {
            contentHelper.appendElementRow(title, link);
          }
        }
      }
    }

    if (!request.previewElement && request.url && target) {
      request.previewElement = await Components.ImagePreview.ImagePreview.build(
          target, request.url, false,
          {imageAltText: Components.ImagePreview.ImagePreview.defaultAltTextForImageURL(request.url)});
    }
    if (request.previewElement) {
      contentHelper.appendElementRow(ls`Preview`, request.previewElement);
    }
    return contentHelper.fragment;
  }

We can easily see that the request parameter is of type

`TimelineModel.TimelineModel.NetworkRequest`

NetWorkRequest has the following code:

_didStopRecordingTraceEvents: function()
    {
        var metadataEvents = this._processMetadataEvents();
        this._injectCpuProfileEvents(metadataEvents);
        this._tracingModel.tracingComplete();
        this._resetProcessingState();
        var startTime = 0;
        for (var i = 0, length = metadataEvents.page.length; i < length; i++) {
            var metaEvent = metadataEvents.page[i];
            var process = metaEvent.thread.process();
            var endTime = i + 1 < length ? metadataEvents.page[i + 1].startTime : Infinity;
            this._currentPage = metaEvent.args["data"] && metaEvent.args["data"]["page"];
            for (var thread of process.sortedThreads()) {
                if (thread.name() === WebInspector.TimelineModel.WorkerThreadName && !metadataEvents.workers.some(function(e) { return e.args["data"]["workerThreadId"] === thread.id(); }))
                    continue;
                this._processThreadEvents(startTime, endTime, metaEvent.thread, thread);
            }
            startTime = endTime;
        }
        this._inspectedTargetEvents.sort(WebInspector.TracingModel.Event.compareStartTime);
        this._cpuProfiles = null;
        this._buildTimelineRecords();
        this._buildGPUTasks();
        this._insertFirstPaintEvent();
        this._resetProcessingState();
        this.dispatchEventToListeners(WebInspector.TimelineModel.Events.RecordingStopped);
    },

We can see that endTime is being calculated from:

metaEvent.thread.process()

We can see that metaEvent.page is being set by:

_processMetadataEvents: function()
    {
        var metadataEvents = this._tracingModel.devToolsMetadataEvents();
        var pageDevToolsMetadataEvents = [];
        var workersDevToolsMetadataEvents = [];
        for (var event of metadataEvents) {
            if (event.name === WebInspector.TimelineModel.DevToolsMetadataEvent.TracingStartedInPage)
                pageDevToolsMetadataEvents.push(event);
            else if (event.name === WebInspector.TimelineModel.DevToolsMetadataEvent.TracingSessionIdForWorker)
                workersDevToolsMetadataEvents.push(event);
        }
        if (!pageDevToolsMetadataEvents.length) {
            // The trace is probably coming not from DevTools. Make a mock Metadata event.
            var pageMetaEvent = this._loadedFromFile ? this._makeMockPageMetadataEvent() : null;
            if (!pageMetaEvent) {
                console.error(WebInspector.TimelineModel.DevToolsMetadataEvent.TracingStartedInPage + " event not found.");
                return {page: [], workers: []};
            }
            pageDevToolsMetadataEvents.push(pageMetaEvent);
        }
        var sessionId = pageDevToolsMetadataEvents[0].args["sessionId"] || pageDevToolsMetadataEvents[0].args["data"]["sessionId"];
        this._sessionId = sessionId;
        var mismatchingIds = new Set();
        /**
         * @param {!WebInspector.TracingModel.Event} event
         * @return {boolean}
         */
        function checkSessionId(event)
        {
            var args = event.args;
            // FIXME: put sessionId into args["data"] for TracingStartedInPage event.
            if (args["data"])
                args = args["data"];
            var id = args["sessionId"];
            if (id === sessionId)
                return true;
            mismatchingIds.add(id);
            return false;
        }
        var result = {
            page: pageDevToolsMetadataEvents.filter(checkSessionId).sort(WebInspector.TracingModel.Event.compareStartTime),
            workers: workersDevToolsMetadataEvents.filter(checkSessionId).sort(WebInspector.TracingModel.Event.compareStartTime)
        };
        if (mismatchingIds.size)
            WebInspector.console.error("Timeline recording was started in more than one page simultaneously. Session id mismatch: " + this._sessionId + " and " + mismatchingIds.valuesArray() + ".");
        return result;
    }

Upvotes: 4

Related Questions