{"action":"created","issue":{"url":"https://api.github.com/repos/Shopify/graphql-batch/issues/27","repository_url":"https://api.github.com/repos/Shopify/graphql-batch","labels_url":"https://api.github.com/repos/Shopify/graphql-batch/issues/27/labels{/name}","comments_url":"https://api.github.com/repos/Shopify/graphql-batch/issues/27/comments","events_url":"https://api.github.com/repos/Shopify/graphql-batch/issues/27/events","html_url":"https://github.com/Shopify/graphql-batch/issues/27","id":185960216,"number":27,"title":"Instrumentation","user":{"login":"tmeasday","id":132554,"avatar_url":"https://avatars.githubusercontent.com/u/132554?v=3","gravatar_id":"","url":"https://api.github.com/users/tmeasday","html_url":"https://github.com/tmeasday","followers_url":"https://api.github.com/users/tmeasday/followers","following_url":"https://api.github.com/users/tmeasday/following{/other_user}","gists_url":"https://api.github.com/users/tmeasday/gists{/gist_id}","starred_url":"https://api.github.com/users/tmeasday/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tmeasday/subscriptions","organizations_url":"https://api.github.com/users/tmeasday/orgs","repos_url":"https://api.github.com/users/tmeasday/repos","events_url":"https://api.github.com/users/tmeasday/events{/privacy}","received_events_url":"https://api.github.com/users/tmeasday/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-10-28T16:02:15Z","updated_at":"2016-11-02T03:33:51Z","closed_at":null,"body":"Following up from https://github.com/rmosolgo/graphql-ruby/pull/354#issuecomment-256810751:\n\n@dylanahsmith : \n\n> For graphql-batch I would just recommend using Promise.map_value to get the end of the field resolution:\n\n``` ruby\nclass MyFieldInstrumentation\n  def instrument(type, field)\n    old_resolve_proc = field.resolve_proc\n    new_resolve_proc = ->(obj, args, ctx) {\n      Rails.logger.info(\"#{type.name}.#{field.name} START: #{Time.now.to_i}\")\n      result = old_resolve_proc.call(obj, args, ctx)\n      Promise.map_value(result) do |value|\n        Rails.logger.info(\"#{type.name}.#{field.name} END: #{Time.now.to_i}\")\n        value\n      end\n    }\n\n    field.redefine do\n      resolve(new_resolve_proc)\n    end\n  end\nend\n```\n\nActually the above does not work (or at least not in a particularly useful way). The problem is that the executor does not necessarily run the loader associated with the field immediately, instead it may wait for some other loaders (or fields I suppose) to execute first. So the \"start time\" logged above (when the field is added to the loader), is not really \"correct\", in terms of the work done to fetch the field.\n\nAs an example, if I run a query against our [example GitHunt server](https://github.com/apollostack/githunt-api-rails) that looks something like:\n\n```\n{\n  entries {\n     # this field goes to a batch loader that talks to github\n     postedBy\n     # this field goes to another github batch loader\n     repository\n     # this field goes to a simple SQL batch loader\n     vote\n  }\n}\n```\n\nYou end up seeing traces that look like:\n\n<img width=\"837\" alt=\"screenshot 2016-10-28 08 54 09\" src=\"https://cloud.githubusercontent.com/assets/132554/19813021/b1c1003e-9cec-11e6-9b69-5f39ef2cc198.png\">\n\nNote in the above that the start time of all the fields is more or less the same (as the executor runs over the set of entries, and they are all added to the various loaders), and the total time is \"cumulative\". In actuality the `vote` loader is more or less instantaneous (running against a local sqlite db in this case), and a correct start time for those fields should really be at the _end_ of the `repository` loader (so I guess 2.03ms in this SS).\n---\n\nThis is why I think for proper instrumentation of the batch loader I think we need to know two things:\n1. What time a loader _actually_ starts.\n2. Which fields the loader is running for.\n\nThe first part is trivial I suppose, but the second seems tricky.\n"},"comment":{"url":"https://api.github.com/repos/Shopify/graphql-batch/issues/comments/257763261","html_url":"https://github.com/Shopify/graphql-batch/issues/27#issuecomment-257763261","issue_url":"https://api.github.com/repos/Shopify/graphql-batch/issues/27","id":257763261,"user":{"login":"tmeasday","id":132554,"avatar_url":"https://avatars.githubusercontent.com/u/132554?v=3","gravatar_id":"","url":"https://api.github.com/users/tmeasday","html_url":"https://github.com/tmeasday","followers_url":"https://api.github.com/users/tmeasday/followers","following_url":"https://api.github.com/users/tmeasday/following{/other_user}","gists_url":"https://api.github.com/users/tmeasday/gists{/gist_id}","starred_url":"https://api.github.com/users/tmeasday/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tmeasday/subscriptions","organizations_url":"https://api.github.com/users/tmeasday/orgs","repos_url":"https://api.github.com/users/tmeasday/repos","events_url":"https://api.github.com/users/tmeasday/events{/privacy}","received_events_url":"https://api.github.com/users/tmeasday/received_events","type":"User","site_admin":false},"created_at":"2016-11-02T03:33:51Z","updated_at":"2016-11-02T03:33:51Z","body":"Some expanded current thinking of data to collect: https://github.com/apollostack/optics-agent/blob/pcarrier/proposals/timing/proposals/timing.md"}}
{"actor":{"display_login":"tmeasday"}}