What is the right way to log a request time using the apollo graphql client?

Question

I'm doing some application profiling on a react native application and I'm seeing pretty big differences between the request times that I'm getting using the apollo-link-logger (as well as the links I've rolled on my own) and the Android profiler's networking lane. For a ~600ms request in the profiler I'm seeing upwards of 2 seconds from the middle ware that uses the apollo link system.

There isn't much going on in my own link (below)

const metricsLink = new ApolloLink((operation, forward) => {

    const { operationName } = operation
    const startTime = new Date().getTime()
    const observable = forward(operation)
    observable.subscribe({
        complete: () => {
            const elapsed = new Date().getTime() - startTime
            console.warn(`[METRICS][${operationName}] (${elapsed}) complete`)
        }
    })

    return observable
})

It seems like its going to end up factoring in the time it takes apollo to manage this request chain as well. I've confirmed that this isn't a general issue with the app by fetching from other endpoints directly with fetch and comparing those times with the profiler times (which match).

Should I expect this to actually reflect the request time? Where might the rest of the time be going between the native network request and the time I'm seeing in the apollo client?

Do you have other links/middleware in place? What quantity do you want to measure exactly? — marktani, Jun 08 '19 at 09:47
I've removed other links for the purpose of this experiment. I want to measure the actual time we wait for the network request, which is what I'm seeing when I use the android profiler. At the very least, I need to understand what the difference between the time I'm measuring and the real network time I see in the profiler is if I'm ever going to try to improve performance. Especially if that difference can be this large. — Anthony Naddeo, Jun 08 '19 at 17:26
I am not sure if this could account for such a high difference, but Apollo client does more than handling the network request. Parsing the incoming JSON, writing it to the cache, etc. — marktani, Jun 08 '19 at 19:38
Yeah that must be the case. I actually opened an issue about this (https://github.com/apollographql/apollo-link/issues/1077). I know where the network request time would need to be logged but I can't really get at it from here. — Anthony Naddeo, Jun 08 '19 at 23:27
There is an example in the Context documentation doing exactly that: https://www.apollographql.com/docs/link/overview/#context The idea, basically, is to create a Link to set the start time and another one that computes the elapsed time. Have you considered this approach? — Geraldo B. Landre, Aug 20 '19 at 18:10

score 2 · Answer 1 · answered Oct 31 '19 at 11:22

From the Apollo Link docs, there is an example to measure time using link composition

Note: I've modified the example to use performance.now() instead of new Date()based on this other SO answer

const timeStartLink = new ApolloLink((operation, forward) => {
  operation.setContext({ start: performance.now() })
  return forward(operation)
})

const logTimeLink = new ApolloLink((operation, forward) => {
  return forward(operation).map(data => {
    // data from a previous link
    const time = performance.now() - operation.getContext().start
    console.log(`operation ${operation.operationName} took ${time} to complete`)
    return data
  })
})

const link = timeStartLink.concat(logTimeLink)

Anthony Naddeo · Accepted Answer · 2019-08-23T17:23:07.193

The issue (at least in the version I was using) was that the Zen Observable (used by Apollo in these links) executes its logic every time the subscribe call is made. That meant that I got double requests being sent because I had two links and each one called subscribe and forwarded the already created observable. My workaround was to create new observables each time and hook them up to the observable that the prior link passed down.

const metricsLink = new ApolloLink((operation, forward) => {

    const { operationName } = operation
    const startTime = new Date().getTime()
    const observable = forward(operation)

    // Return a new observable so no other links can call .subscribe on the
    // the one that we were passsed.
    return new Observable(observer => {
        observable.subscribe({
            complete: () => {
                const elapsed = new Date().getTime() - startTime
                console.warn(`[METRICS][${operationName}] (${elapsed}) complete`)
                observer.complete()
            },
            next: observer.next.bind(observer),
            error: error => {
                // ...
                observer.error(error)
            }
        })
    })
})

This seems like an oversight to me, but at least I have a workaround.

What is the right way to log a request time using the apollo graphql client?

2 Answers2