async-graphql: Slow compile and cargo check

We have a relatively small graphql schema but it takes a long time for cargo check to complete (~20s). Is this a common problem or is there any known issue that can causes the long check times? Happy to provide more details if needed.

Sources are at: https://github.com/openmsupply/remote-server/tree/develop/graphql/src/schema

About this issue

  • Original URL
  • State: open
  • Created 2 years ago
  • Reactions: 1
  • Comments: 32 (11 by maintainers)

Commits related to this issue

Most upvoted comments

It works! My crazy idea to have an “outer layer” macro that strips out all the async-graphql macros (when cargo check is running in rust-analyzer) actually works! (this maybe is not surprising to experienced rustacians, but as a newcomer from JS/TS, Rust’s macro system feels really empowering)

The cargo check command is now down to 2.5 seconds, which is such a relief relative to the 6 second timings I was getting just a couple days ago.

What drawbacks does it have?

Not much! Basically, it just means that when you hover over the async-graphql macros in your IDE, you no longer see rust-doc descriptions and such.

That’s really not a big deal though, because there are only six macros that get stripped (graphql, Object, Subscription, SimpleObject, MergedObject, MergedSubscription), so once you know what those 6 macros do, there is not much point to having their rust-doc info show up in your IDE like that.

How do you use it?

Pretty straightforward: any structs where you use the async-graphql macros, simple wrap that area of code with the wrap_async_graphql macro, like so:

wrap_async_graphql!{

#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct CommandRun {
    field1: String;
    #[graphql(name = "field99")]
    field2: i64;
}

}

There is one other change you must make:

// replace this
Schema::build(QueryRoot::default(), MutationRoot::default(), SubscriptionRoot::default())

// with this
wrap_agql_schema_build!{
    Schema::build(QueryRoot::default(), MutationRoot::default(), SubscriptionRoot::default())
}

This wrap_agql_schema_build macro is necessary so that when the rest of the async-graphql macros are stripped, the code that’s meant to call the schema-building still compiles. All it does is that, when the macro-stripping is enabled, it replaces the Schema::build expression with this:

Schema::build(EmptyMutation, EmptyMutation, EmptySubscription)

(If a new macro seems overkill for this, it may be possible to use a more standard replacement approach, like the built-in cfg! macro or something…)

Anyway, while the output-token-caching approach in my previous post is more flexible, this “dumber” macro-stripping is probably better for async-graphql, since it gives even better speeds, avoids some complications with caching, and you don’t lose much. (since the macros are almost completely just for outputting that GraphQL API, not for in-IDE introspection or the like – at least for the way I’m currently using it)

While I will likely work more on the output-token-caching approach eventually, for now this solves my concerns well, and lets me resume work on my actual project without frustration.

Anyway, I hope to eventually make a separate crate for this system, so that other users of async-graphql can easily speed up their cargo-check times as well.

Until then, you can find the initial source-code for it here (in the rust-macros sub-crate of my larger project): https://github.com/debate-map/app/blob/d55d0043b4cdaea558adf70840ab6d902df04cf8/Packages/rust-macros/src/wrap_async_graphql.rs

Other than the instructions already mentioned, the only other thing needed is to have STRIP_ASYNC_GRAPHQL=1 as an environment-variable for your in-IDE cargo check executions. In VSCode, this is accomplished by adding the following to your project’s .vscode/settings.json:

"rust-analyzer.server.extraEnv": {
    "STRIP_ASYNC_GRAPHQL": "1",
},

(I might be able to remove this requirement later on, if I figure out a way to detect the rust-analyzer execution-context automatically.)

So today I thought:

If I can use higher-level macros to strip out async-graphql’s macro during cargo-check, why can’t I do the same thing for other slow macros like Serialize and Deserialize?

Turns out, you absolutely can. I now have a combined wrap_slow_macros macro (source here; new wrap_serde_macros macro source here) that I wrap around all my structs (well, the ones that use Serialize, Deserialize, or any of the async-graphql macros).

It strips out the async-graphql macros, and replaces Serialize and Deserialize with “stubs”, that just produce this:

impl serde::Serialize for #struct_name {
    fn serialize<__S>(&self, __serializer: __S) -> serde::__private::Result<__S::Ok, __S::Error> where __S: serde::Serializer {
        Err(serde::ser::Error::custom("This is a placeholder generated by the Serialize_Stub macro, for quick resolution during cargo-check. You should not be seeing this at runtime."))
    }
}
impl <'de> serde::Deserialize<'de> for #struct_name {
    fn deserialize<__D>(__deserializer:__D) -> serde::__private::Result<Self, __D::Error> where __D: serde::Deserializer<'de> {
        Err(serde::de::Error::custom("This is a placeholder generated by the Deserialize_Stub macro, for quick resolution during cargo-check. You should not be seeing this at runtime."))
    }
}

With the optimization above, my cargo check time is now down to a pleasant 1.5 seconds (it was 6.1s just a few days ago), without having to split my codebase into subcrates or the like. 😄

I’m quite relieved! This was my biggest concern with Rust (slow macros for important crates like serde and async-graphql), but the flexibility of Rust’s macro-system has enabled me to just skip/stub whatever macros I want to at cargo-check time – retaining fast in-IDE type-checking.

I also have been having very slow “cargo check” times in my Rust project: https://github.com/debate-map/app/tree/master/Packages/app-server-rs/src/db

In Rust 1.58, merely changing the string in a println would take 6 seconds for the cargo check call to complete (as called by rust-analyzer automatically on file-save).

In Rust 1.59 (just updated to see if it would help), this same thing now takes 17 seconds! (I cannot wait 17 seconds every time I change one letter just to see syntax/type errors!)

I eventually narrowed down one of the slowdowns to being due to the SimpleObject macro.

Specifically, given these structs:

Code for database structs

#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct Map {
    id: ID,
    accessPolicy: String,
    name: String,
    note: Option<String>,
    noteInline: Option<bool>,
    rootNode: String,
    defaultExpandDepth: i32,
    nodeAccessPolicy: Option<String>,
    featured: Option<bool>,
    editors: Vec<String>,
    creator: String,
    createdAt: i64,
    edits: i32,
    editedAt: Option<i64>,
    extras: serde_json::Value,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct Term {
    id: ID,
    accessPolicy: String,
    creator: String,
    createdAt: i64,
    name: String,
    forms: Vec<String>,
    disambiguation: Option<String>,
    r#type: String,
    definition: String,
    note: Option<String>,
    attachments: Vec<serde_json::Value>,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct AccessPolicy {
    id: ID,
    creator: String,
    createdAt: i64,
    name: String,
    permissions: serde_json::Value,
    permissions_userExtends: serde_json::Value,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct Media {
    id: ID,
    accessPolicy: String,
    creator: String,
    createdAt: i64,
    name: String,
    r#type: String,
    url: String,
    description: String,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct CommandRun {
    id: ID,
    actor: String,
    runTime: i64,
    public_base: bool,
    commandName: String,
    commandPayload: serde_json::Value,
    returnData: serde_json::Value,
    rlsTargets: serde_json::Value,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct Proposal {
    id: ID,
    r#type: String,
    title: String,
    text: String,
    creator: String,
    createdAt: i64,
    editedAt: Option<i64>,
    completedAt: Option<i64>,
}

#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct UserInfo {
    id: ID,
    proposalsOrder: Vec<String>,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct MapNodeEdit {
    id: ID,
    map: String,
    node: String,
    time: i64,
    r#type: String,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct NodeChildLink {
    id: ID,
    creator: String,
    createdAt: i64,
    parent: String,
    child: String,
    group: String,
    orderKey: String,
    form: Option<String>,
    seriesAnchor: Option<bool>,
    seriesEnd: Option<bool>,
    polarity: Option<String>,
    c_parentType: Option<String>,
    c_childType: Option<String>,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct MapNodePhrasing {
    id: ID,
    creator: String,
    createdAt: i64,
    node: String,
    r#type: String,
    text_base: String,
    text_negation: Option<String>,
    text_question: Option<String>,
    note: Option<String>,
    terms: Vec<serde_json::Value>,
    references: Vec<String>,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct NodeRating {
    id: ID,
    accessPolicy: String,
    node: String,
    r#type: String,
    creator: String,
    createdAt: i64,
    value: f32,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct MapNodeRevision {
    id: ID,
    node: String,
    creator: String,
    createdAt: i64,
    phrasing: serde_json::Value,
    phrasing_tsvector: String,
    note: Option<String>,
    displayDetails: Option<serde_json::Value>,
    equation: Option<serde_json::Value>,
    references: Option<serde_json::Value>,
    quote: Option<serde_json::Value>,
    media: Option<serde_json::Value>,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct MapNodeTag {
    id: ID,
    creator: String,
    createdAt: i64,
    nodes: Vec<String>,
    labels: Option<serde_json::Value>,
    mirrorChildrenFromXToY: Option<serde_json::Value>,
    xIsExtendedByY: Option<serde_json::Value>,
    mutuallyExclusiveGroup: Option<serde_json::Value>,
    restrictMirroringOfX: Option<serde_json::Value>,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct MapNode {
    id: ID,
    creator: String,
    createdAt: i64,
    r#type: String,
    rootNodeForMap: Option<String>,
    c_currentRevision: Option<String>,
    accessPolicy: String,
    multiPremiseArgument: Option<bool>,
    argumentType: Option<String>,
    extras: serde_json::Value,
}
#[derive(SimpleObject, Clone, Serialize, Deserialize)]
pub struct Share {
    id: ID,
    creator: String,
    createdAt: i64,
    name: String,
    r#type: String,
    mapID: Option<String>,
    mapView: serde_json::Value,
}

If I make no changes except removing the SimpleObject macro from the above structures, it speeds up my cargo check times by ~4.5 seconds.

4.5 seconds doesn’t sound that bad? Well, it’s acceptable if the 4.5 seconds was occurring only when I am running cargo build or the like. But that 4.5 seconds becomes painful when it’s slowing down every instance of basic syntax/type checking in my IDE.

Also keep in mind that the 4.5 seconds is only one part of the overhead – there is more overhead, eg. in the Object macro used for adding queries/subscriptions/mutations fields to the graphql API, but I’m ignoring those parts for now to focus on the SimpleObject slowdown. Altogether, the “db/XXX” files end up adding 12+ seconds to my cargo check time on rust 1.59, which is just too much.

If more details are desired, here is a text log I wrote detailing my cargo-check timing process:

Log of slowdown investigation

  1. Took 14 seconds for cargo-check to complete, from a simple string change in pgclient.rs. (time with “cargo check” text showing)
  2. Did it more times, and got: 6s, 5s, 5s
  3. Added a println!(“…”) call in start_streaming_changes func, and took the same (6s).
  4. Updated from Rust 1.58 to 1.59, and now the fastest I can get is 17s!
  5. When I mod-exclude all the files under “src/db” (as well as the imports/usages of them), the cargo-check takes ~1.5s.
  6. When I add back the mod-include for “db/_general”: ~2.5s
  7. From now on, I’m doing the string-change test using a simple println!("TestXXX"); line in main.rs, just before the “mod …” lines. (makes it easier to test impact of commenting files out)
  8. With all db files mod-included again (though imports/usages of them still commented): ~13s
  9. With 9 of the 19 db files mod-excluded: ~8s
  10. With 13 of the 19 db files mod-excluded: ~5s
  11. With only “db/_general” and “db/terms” left mod-included: ~3s
  12. With Term struct (with From impl) duplicated to 5 copies: ~4s [duplicates removed for future steps]
  13. With only users, user_hiddens, and global_data removed: ~11s
  14. With all code after the main struct+FromImpl (in each db file) removed: ~7s
  15. With all macros used on/in the main db-structs removed: ~2s
  16. With just the serde Serialize and Deserialize macros added-back: ~3s
  17. With the Clone macro also added back: ~3s
  18. With the SimpleObject macro also added back: ~7.5s

Haha, I think the only way is to upgrade the computer. 😂 Or, as @clemens-msupply did, split a project into many sub crates.

I tried updating from Rust 1.59 to Rust 1.60.0-beta.3 (as per a comment on the Discord saying 1.59 had incremental-compilation broken), but the 4.5 second cargo-check cost from the SimpleObject macro was still present.

However, in a terminal I then ran cargo clean, followed by cargo check, and from that point on, I was getting much better timings, for the stripped down code:

  • ~3.6s with the SimpleObject macros in use
  • ~1.8s with the SimpleObject macros removed

So on Rust 1.60, it seems the overhead of using SimpleObject is 1.8s, rather than 4.5s as seen on 1.59.

When I revert all the stripping-down I did, the overall time for cargo check (after the change of a println string) is now back to the ~6s I was getting on 1.59.

For me, that still feels quite slow; is 6s considered acceptable for cargo-check for even smallish programs like this? (I’m thinking of TypeScript for example, where syntax/type checking generally shows up in the IDE in under 1 second, even in much larger codebases)

Anyway, I will see if I can speed it up somehow…

I tried to split our big Query struct into two structs and then merge them back like in https://async-graphql.github.io/async-graphql/en/merging_objects.html, but this didn’t help, i.e. editing the smaller new Query struct resulted in the same long check times.

This definitely does not reduce check time. 😂

I haven’t tried to split our graphql crate into multiple crates yet.

But this is possible, splitting into multiple crates can make full use of multi-core cpu.

I don’t think it makes much sense to do this, in fact I never bothered with this problem, usually I only check it once with cargo clippy after I have written the code and tested it.