Track request duration

[simplenotezy]

Request Statement

I'd like a way to track request durations. Initially I thought I could simply create an interceptor that would keep track of each request and then using StopWatch. However, it's been proven to log much longer duration than ngrok is reporting.

This is the code that reports invalid request duration (e.g. code reports 600ms, but ngrok reports 53ms).

import 'dart:convert';

import 'package:crypto/crypto.dart';
import 'package:dio/dio.dart';

String generateMd5(String input) {
  return md5.convert(utf8.encode(input)).toString();
}

class RequestTimeInterceptor extends Interceptor with Loggable {
  String get debugLogContext => 'SlowRequests';

  Map<String, Stopwatch> _requests = {};

  _isGraphqlRequest(RequestOptions options) {
    return options.path.contains('graphql');
  }

  _getRequestId(RequestOptions options) {
    if (_isGraphqlRequest(options)) {
      final encoded = _getRequestName(options) + options.data['variables']?.toString();
      final id = generateMd5(encoded);

      return id;
    }

    return generateMd5(options.path + options.data.toString());
  }

  _getRequestName(RequestOptions options) {
    if (_isGraphqlRequest(options)) {
      return options.data['operationName'] ?? 'Unknown GraphQL request';
    }

    return options.path;
  }

  @override
  void onRequest(RequestOptions options, RequestInterceptorHandler handler) {
    _requests[_getRequestId(options)] = Stopwatch()..start();
    return super.onRequest(options, handler);
  }

  @override
  void onResponse(Response response, ResponseInterceptorHandler handler) {
    _requestStopped(response.requestOptions);

    return super.onResponse(response, handler);
  }

  @override
  void onError(DioException err, ErrorInterceptorHandler handler) {
    _requestStopped(err.requestOptions);

    return super.onError(err, handler);
  }

  /// Called when a request is stopped (either by error or success)
  _requestStopped(RequestOptions options) {
    final stopWatch = _requests[_getRequestId(options)];

    stopWatch?.stop();

    recordLog('Request to ${_getRequestName(options)} took ${stopWatch?.elapsedMilliseconds} ms');

    _requests.remove(_getRequestId(options));
  }
}

Solution Brainstorm

No response

[simplenotezy]

I should note that we are using the http2 adapter by the way

[AlexV525]

As far as I know, ngrok is a backend service, correct? What makes you think that clients request duration should equal to server's?

[kuhnroyal]

You can look at how Sentry traces the time here: https://github.com/getsentry/sentry-dart/blob/main/dio/lib/src/breadcrumb_client_adapter.dart

[simplenotezy]

As far as I know, ngrok is a backend service, correct? What makes you think that clients request duration should equal to server's?

They report the response time it takes from sending the request to receiving the answer. Same as I would expect this interceptor to do. I also tried verifying by proxying through Charles; same incorrect results for some reason. And it's not just a few ms. It's a request taking 100ms is sometimes tracked as 600ms with stopwatch; so I am simply trying to understand what layers might be in between the interceptors and what can be done to get more accurate reports

[simplenotezy]

You can look at how Sentry traces the time here: https://github.com/getsentry/sentry-dart/blob/main/dio/lib/src/breadcrumb_client_adapter.dart

Nice! Will check it out

[simplenotezy]

so I am simply trying to understand what layers might be in between the interceptors and what can be done to get more accurate reports

Seems like this answers my question: https://github.com/getsentry/sentry-dart/blob/main/dio/lib/src/breadcrumb_client_adapter.dart#L12

[AlexV525]

@kuhnroyal Did we match the circumstance to close the issue? Could we implement a duration interceptor or a general adapter on our own?

[kuhnroyal]

I don't know, we could add the timing to the LogInterceptor. Other than that, I see no point.

[egfconnor]

I am trying to accomplish something similar and have a custom RequestTimeInterceptor working. The time I calculate using a stopwatch between onRequest and onResponse in the interceptor matches roughly what the DevTools Network page shows. What is strange though is there is a ~200 ms delay before onRequest is called.

Some sample code:

final dio = Dio();
dio.interceptors.add(
  RequestTimeInterceptor(),
);

print('Started at ${DateTime.now().toString()}');

final response = await dio.get<String>('<my_api_url>');

The interceptor is just printing times in onRequest and onResponse and I see the following in the debug console:

flutter: Started at 2024-12-11 09:13:51.122295
flutter: onRequest at 2024-12-11 09:13:51.353484
flutter: onResponse at 2024-12-11 09:13:51.819328

Does anyone with more understanding of Dio know what happens between the call to .get() and the interceptor calling onRequest()?

Edit: I think this may be the time that it takes to setup the socket? I don't think I should consider that part of the request time for telemetry reporting.