Unknown overhead

[guilherme]

Hi,

We have two applications with graphql-ruby, and one of them has, apparently, a performance overhead (~ 400ms extra). We're seeing a big overhead on newRelic on one, and the other one doesn't have this overhead.

We've double check everything regrading newrelic configuration.

They use the same version: 1.8.0.pre10, also ruby version. they both are multiplexing, and have the same complexity and depth configs. We profiled both of them:

Here's the profile of the one that has a big overhead:

Here's the profile of the one that has no visible overhead.

)

Have you people seen this in the wild?

Thank you,

[rmosolgo]

Hey there! Thanks for sharing this profiling info, that's really interesting. There are some known performance issues (#1172 , #861), but I don't immediately recognize this as being the same as those.

One thing that really stands out to me is, in the first graph, look how long is spent in the lexer (eg .scan, GraphQL::Language::Lexer). In these two examples, how do the incoming query strings compare? Is it using the same query?

Also, it looks like the second graph is just part of the profile, is that right? If so, is it possible to share more of it? I can't quite figure out what I'm looking at there 😬

[guilherme]

One thing that really stands out to me is, in the first graph, look how long is spent in the lexer (eg .scan, GraphQL::Language::Lexer). In these two examples, how do the incoming query strings compare? Is it using the same query?

No, one has multiple fragments and the other one is simpler.

query ($_workId: ID!) {
      work(workId: $_workId) {
        ...FeedGrid
        __typename
      }
    }

    fragment FeedGrid on Work {
      id
      matureContent
      ...FeedGridItem
      __typename
    }

    fragment FeedGridItem on Work {
      id
      title
      url
      __typename
      ... on Work {
        artistId
      }
      ... on Work { 
        id
      }
      ... on Work {
        id
      }
      ... on Work {
        id
      }
    }

Simpler:

{\n  workRecommendations(limit: 5) {\n    id\n    workId\n  }\n}

Also, it looks like the second graph is just part of the profile, is that right? If so, is it possible to share more of it? I can't quite figure out what I'm looking at there 😬

Sorry, it was too long to fit on a screen.

I tried to make it fit on a screen now:

One thing to note tough, is that we're loading the schema from file, instead of ruby classes. By our tests locally this doesn't change the performance. Perhaps, there's something in there that we don't know.

  GraphQL::Schema.from_definition(File.read(path), default_resolve: resolvers)

[guilherme]

oh, by the way: the total time is 3.8s

[rmosolgo]

Hi, there's been a lot of work to improve GraphQL-Ruby's runtime performance, including a new runtime and analyzer.

Looking at the flamegraph above, it looks like the longest time is spent in Curl#select, which I think means it's waiting for an external service to respond. Here are those segments:

I hope to provide support for backgrounded IO in #2483 , which might help.

I don't have plans to work more from this issue, so I'm closing it. If you try the new runtime options and still have GraphQL-related latency, please open a new issue with new flamegraphs!