Lots of events fired for a simple GraphQL query

[Wiejeben]

Description

Today I noticed my GraphQL queries taking ages (minimum of 1 second). Sending the same query again only takes about 100 ms because of caching. Changing the query or variables would take 1+ second again.

Did some digging in the Yii Debugger and noticed 3671 events were fired, mostly defineBehaviors, craft\events\DefineBehaviorsEvent, craft\models\EntryType and init yii\base\Event craft\models\EntryType. However so far I have only created 15 entrytypes.

With this I also noticed more MySQL queries than I would reasonably expect.

I compared this behaviour with a website in production. Running running 3.4.27 its also making makes 4271 events.

Hopefully some improvements can be made making GraphQL more lightweight! I'm not too sure what's happening underneath the hood but if I were to guess than it is probably rebuilding the entire GraphQL schema on every single new call? Just before the thousands of repeated events, RegisterGqlTypesEvent is triggered.

Steps to reproduce

1. Send a really simple GraphQL call to this simple Single, both GraphiQL explorer as external API calls give the same slow result.

{
  entry(section: "homepage") {
    id
    title
    slug
  }
}

This MySQL query is being called 60 times total, with every layoutId was being called 3 times.
SELECT `fields`.`id`, `fields`.`dateCreated`, `fields`.`dateUpdated`, `fields`.`groupId`, `fields`.`name`, `fields`.`handle`, `fields`.`context`, `fields`.`instructions`, `fields`.`translationMethod`, `fields`.`translationKeyFormat`, `fields`.`type`, `fields`.`settings`, `fields`.`uid`, `fields`.`searchable`, `flf`.`layoutId`, `flf`.`tabId`, `flf`.`required`, `flf`.`sortOrder` FROM `fields` `fields` INNER JOIN `fieldlayoutfields` `flf` ON `flf`.`fieldId` = `fields`.`id` INNER JOIN `fieldlayouttabs` `flt` ON `flt`.`id` = `flf`.`tabId` WHERE `flf`.`layoutId`=24 ORDER BY `flt`.`sortOrder`, `flf`.`sortOrder

This MySQL query is being called 90 times:
SELECT `id`, `sectionId`, `fieldLayoutId`, `name`, `handle`, `sortOrder`, `hasTitleField`, `titleFormat`, `uid`, `titleTranslationMethod`, `titleTranslationKeyFormat` FROM `entrytypes` WHERE `dateDeleted` IS NULL

Additional info

• Craft version: 3.5.4
• PHP version: 7.2.33
• Database driver & version: MySQL 5.7.31
• Plugins & versions: Redactor 2.7.1, Redirect Manager 1.1.1, SEOmatic 3.3.15

No modules, a very much vanilla headless Craft setup.

[Marcuzz]

Not sure if it's completely related, but I seem to be having a similar issue where queries get completely stuck in PostgreSQL and even after I delete the service from Kubernetes the query is still attempting to run, indefinitely, causing the PostgreSQL instance to have 100% CPU constantly and the Craft CMS pod to time out constantly when loading the admin control panel or any GraphQL query.

In our case it's a query that attempts to load all of our elements it looks like, it's a monster query: redacted

I'm still trying to investigate the actual reason behind my problem though, but I thought it'd be at least somewhat relevant to the issue at hand!

After further investigation I honestly think it was the DB instance it ran on as it runs well on a new one, so I think it's safe to say you can disregard my comment completely 😅

[brandonkelly]

@Wiejeben Events themselves shouldn’t be a problem. And many of them will only fire if Dev Mode is enabled or there is an active event listener on them. If you send your Composer files and a database backup over to support@craftcms.com, plus an example GraphQL query, we can try profiling it and see if there are any opportunities to speed things up in your case.

@Marcuzz Sounds unrelated, please post a new issue, or maybe just write into support@craftcms.com as this will likely be something environmental. (The SQL query you posted looks like a typical entry query to me.)

[Wiejeben]

Send!

[Wiejeben]

I had to create a few more sections and fields which drastically increased the amount of events. Even sending the { ping } query takes about X-Debug-Duration: 2,502 with 8290 events. Each individual event takes less than 0.001 seconds but multiplying that by a few thousand of course results in a very noticeable slowdown.

So I did some digging myself. Culprit is mainly \craft\gql\types\generators\EntryType::generateTypes, which if I measure the time it takes with microtime(true) about 1.5 seconds.

Is there any way to perhaps make generating the GraphQL query definitions be cached globally and refreshed at every configuration change instead of every query/variable change? I'm really curious to finding a solution to this!

Note: Turning devMode off reduces the amount of events with about 1000 and improves the load time with about .5 seconds

[andris-sevcenko]

Having xDebug enabled significantly increases operation time for everything - have you tried turning it off to see what the timings are?

[Wiejeben]

@andris-sevcenko Turning everything off indeed improves the performance. However EntryType::generateTypes(...) is still called which is causing scaling issues.

Executing the { ping } query now takes between 1.2 and 1.4 seconds.

However lets say my blog index (with 15 articles) takes about 2.1 seconds:

query blogIndex($uri: String) {
  ...seomatic
  entry(section: "blogIndex") {
    ... on blogIndex_blogIndex_Entry {
      title
      subTitle
    }
  }
  articles: entries(section: "blog") {
    ...blogCard
  }
  articlesCount: entryCount(section: "blog")
}

fragment seomatic on Query {
  seomatic(uri: $uri) {
    ... on SeomaticInterface {
      metaTitleContainer
      metaTagContainer
      metaLinkContainer
      metaJsonLdContainer
    }
  }
}

fragment cardImageUrls on AssetInterface {
  urlLarge: url @transform(handle: "cardLarge", immediately: false)
  urlMedium: url @transform(handle: "cardMedium", immediately: false)
  urlSmall: url @transform(handle: "cardSmall", immediately: false)
  urlXsmall: url @transform(handle: "cardXsmall", immediately: false)
}

fragment blogCard on blog_blog_Entry {
  title
  slug
  dateCreated @formatDateTime(format: "d M Y")
  blogAuthor
  blogCategory(limit: 1) {
    title
  }
  pageImages(limit: 1) {
    title
    focalPoint
    ...cardImageUrls
  }
}

Same goes for the blog detail, about 2.1 seconds:

query blogShow($uri: String, $slug: [String]) {
  ...seomatic
  entry(section: "blog", slug: $slug) {
    ... on blog_blog_Entry {
      title
      slug
      dateCreated @formatDateTime(format: "d M Y")
      blogAuthor
      blogCategory(limit: 1) {
        title
      }
      pageImages {
        title
        focalPoint
        ...pageImageUrls
      }
      pageContentMatrix {
        ...pageContentMatrix
      }
    }
  }
  articles: entries(section: "blog", limit: 4) {
    ...blogCard
  }
}

fragment seomatic on Query {
  seomatic(uri: $uri) {
    ... on SeomaticInterface {
      metaTitleContainer
      metaTagContainer
      metaLinkContainer
      metaJsonLdContainer
    }
  }
}

fragment pageImageUrls on AssetInterface {
  urlLarge: url @transform(handle: "pageImageLarge", immediately: false)
  urlSmall: url @transform(handle: "pageImageSmall", immediately: false)
}

fragment linkIt on linkField_Link {
  url
  type
  text
  target
}

fragment contentImageUrls on AssetInterface {
  urlLarge: url @transform(handle: "contentImageLarge", immediately: false)
  urlSmall: url @transform(handle: "contentImageSmall", immediately: false)
}

fragment pageContentMatrix on pageContentMatrix_MatrixField {
  ... on MatrixBlockInterface {
    id
    typeHandle
  }
  ... on pageContentMatrix_text_BlockType {
    blockContent
  }
  ... on pageContentMatrix_quote_BlockType {
    blockContent
    blockSubTitle
  }
  ... on pageContentMatrix_button_BlockType {
    blockPrimary {
      ...linkIt
    }
    blockSecondaryPrefix
    blockSecondary {
      ...linkIt
    }
  }
  ... on pageContentMatrix_image_BlockType {
    blockSubTitle
    image: blockContent {
      title
      id
      ...contentImageUrls
    }
  }
}

fragment cardImageUrls on AssetInterface {
  urlLarge: url @transform(handle: "cardLarge", immediately: false)
  urlMedium: url @transform(handle: "cardMedium", immediately: false)
  urlSmall: url @transform(handle: "cardSmall", immediately: false)
  urlXsmall: url @transform(handle: "cardXsmall", immediately: false)
}

fragment blogCard on blog_blog_Entry {
  title
  slug
  dateCreated @formatDateTime(format: "d M Y")
  blogAuthor
  blogCategory(limit: 1) {
    title
  }
  pageImages(limit: 1) {
    title
    focalPoint
    ...cardImageUrls
  }
}

[andris-sevcenko]

Do you have enableGraphQlCaching set to false, by any chance?

[Wiejeben]

Yes it is enabled. Executing the same query a second time takes less than 0.2 second which is great. However this is a very dynamic website so a lot of content will be updated multiple times per hour, invalidating the cache.

[Wiejeben]

Discussed this with @andris-sevcenko over Discord. GraphQL does run faster on his machine. Caching/serializing \craft\services\Gql::getSchemaDef isn't possible yet.

Will personally be looking into cache warming since the cached response rates are beyond excellent!

[Wiejeben]

Just deployed to our new server setup. Even with the X-Debug tool enabled it's generating uncached GraphQL responses in 0.2 seconds.

I guess my local setup wasn't so fast after all...

[brandonkelly]

Glad to hear that, @Wiejeben! That’s actually pretty impressive if Xdebug is enabled.

[mildlygeeky]

@brandonkelly - So this is interesting - we have a headless site paired with a static site generator, and whenever the site regenerates we are seeing the server spend almost all of its time rebuilding the schema via Gql::getSchemaDef - here is some profiling we did on New Relic to see where we were spending so much time - as you can see, a ton of time is being spent in PHP, and actually very little in MySQL:

We have our rebuild pretty well-optimized (GQL caching as well as GQL batching, on pages with multiple calls), but digging into the API GQL controller I can see that even with GQL caching, it does quite a bit of work pulling the schema definition on every request. Would it be possible for the schema to be cached once the query has been validated? Seems like there is a lot of time being spent here when it probably doesn't have to.

[andris-sevcenko]

@mildlygeeky just opened a new issue for this to keep track.