Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Refactor/remove unecessary inspect calls #84

Conversation

pmargreff
Copy link
Contributor

@pmargreff pmargreff commented Nov 30, 2019

Remove unnecessary inspect calls.

absinthe-graphql/absinthe#573 issue has shown a big percentual time to resolve queries after they're fetched from the database.

After some debug @jeroenvisser101 pointed one of the problems.

... I did some further investigation, and found that the inspect calls are actually made from dataloader: ce9ac3f#diff-cb130db1770f44aedd393088b4d91bcdR252 ...

It seems like some changes were made in the way errors are reported. Dataloader.Ecto seems to rely on errors to update pending batches, because it abuses fetch/3 to check if a value has previously been loaded. If we either added a argument to fetch/3 to toggle detailed errors, or to introduce fetched?/3 and used that in load/3, we would prevent inspect calls.

I got the call and refactored load creating a fetched?/3 function, so it will not pass through unnecessary inspect calls on both kv and ecto implementations.

Debugging the problem summed inspect calls represents 13% of the time (sample above).

'Elixir.Inspect.Atom':inspect/2                                                                   40000     0.18     5363  [      0.13]
'Elixir.Inspect.Algebra':'-container_doc/6-fun-0-'/4                                              50000     0.19     5622  [      0.11]
'Elixir.Inspect.Algebra':nest/2                                                                   10000     0.08     2290  [      0.23]
'Elixir.Inspect.Tuple':inspect/2                                                                  10000     0.05     1577  [      0.16]
'Elixir.Inspect.Map':inspect/3                                                                    10000     0.06     1715  [      0.17]
'Elixir.Inspect.PID':inspect/2                                                                    10000     0.06     1804  [      0.18]
'Elixir.Inspect.Algebra':container_each/6                                                         70000     0.42    12405  [      0.18]
'Elixir.Inspect.Algebra':flex_break/1                                                             50000     0.49    14245  [      0.28]
'Elixir.Inspect.Opts':'__struct__'/0                                                              10001     0.09     2494  [      0.25]
'Elixir.Inspect.Algebra':apply_nesting/3                                                          10000     0.09     2495  [      0.25]
'Elixir.Inspect.Algebra':group/2                                                                  20001     0.09     2775  [      0.14]
'Elixir.Inspect.Algebra':flex_glue/2                                                              50000     0.19     5665  [      0.11]
'Elixir.Inspect.Algebra':join/4                                                                   50000     0.22     6501  [      0.13]
'Elixir.Inspect.Algebra':flex_glue/3                                                              50000     0.22     6523  [      0.13]
'Elixir.Inspect.Atom':color_key/1                                                                 40000     0.32     9400  [      0.23]
'Elixir.Inspect':impl_for/1                                                                       70001     0.32     9406  [      0.13]
'Elixir.Inspect':'impl_for!'/1                                                                    70001     0.67    19677  [      0.28]
'Elixir.Inspect.Algebra':to_doc/2                                                                 70001     0.70    20405  [      0.29]
'Elixir.Inspect.Algebra':color/3                                                                 100001     0.81    23779  [      0.24]
'Elixir.Inspect.Algebra':decrement/1                                                              60000     1.08    31509  [      0.53]
'Elixir.Inspect.Algebra':concat/2                                                                180000     1.25    36417  [      0.20]
'Elixir.Inspect.Algebra':fold_doc/2                                                               60000     1.39    40727  [      0.68]
'Elixir.Inspect.Algebra':format/3                                                                410003     2.97    86865  [      0.21]

After the refactor the same query using Dataloader now goes from something like 11_502_307 to 8_260_419 fn calls. Complete results here.

* Extract fetched?/3 function to not return nor inspect errors while
checking once it will take a long time processing with a lot of
iterations.
* Make fetched independent from fetch_item_from_batch/2 who can make
the time issue occur again.
Copy link
Contributor

@benwilson512 benwilson512 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good in general, just some minor code tweaks.

lib/dataloader/kv.ex Outdated Show resolved Hide resolved
lib/dataloader/ecto.ex Outdated Show resolved Hide resolved
@pmargreff
Copy link
Contributor Author

@benwilson512 ping

@benwilson512 benwilson512 merged commit fa785f8 into absinthe-graphql:master Jan 8, 2020
@benwilson512
Copy link
Contributor

Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants