Get some timing insights for graphql queries

Get some timing insights for graphql queries

Setting up some timing gql information

kibana-import.json

[
  {
    "_id": "e1c11e80-ff05-11e9-9f8f-4b15d29a5698",
    "_type": "visualization",
    "_source": {
      "title": "Timing in Table",
      "visState": "{\"title\":\"Timing in Table\",\"type\":\"table\",\"params\":{\"perPage\":10,\"showPartialRows\":false,\"showMetricsAtAllLevels\":false,\"sort\":{\"columnIndex\":null,\"direction\":null},\"showTotal\":false,\"totalFunc\":\"sum\"},\"aggs\":[{\"id\":\"1\",\"enabled\":true,\"type\":\"avg\",\"schema\":\"metric\",\"params\":{\"field\":\"duration\"}},{\"id\":\"2\",\"enabled\":true,\"type\":\"date_histogram\",\"schema\":\"split\",\"params\":{\"field\":\"ts\",\"timeRange\":{\"from\":\"now-1h\",\"to\":\"now\",\"mode\":\"quick\"},\"useNormalizedEsInterval\":true,\"interval\":\"d\",\"time_zone\":\"Europe/Berlin\",\"drop_partials\":false,\"customInterval\":\"2h\",\"min_doc_count\":1,\"extended_bounds\":{},\"row\":true}},{\"id\":\"3\",\"enabled\":true,\"type\":\"terms\",\"schema\":\"bucket\",\"params\":{\"field\":\"parent.keyword\",\"size\":1000,\"order\":\"desc\",\"orderBy\":\"_key\",\"otherBucket\":false,\"otherBucketLabel\":\"Other\",\"missingBucket\":false,\"missingBucketLabel\":\"Missing\",\"customLabel\":\"Type\"}},{\"id\":\"4\",\"enabled\":true,\"type\":\"count\",\"schema\":\"metric\",\"params\":{}},{\"id\":\"5\",\"enabled\":true,\"type\":\"terms\",\"schema\":\"bucket\",\"params\":{\"field\":\"field.keyword\",\"size\":1000,\"order\":\"desc\",\"orderBy\":\"_key\",\"otherBucket\":false,\"otherBucketLabel\":\"Other\",\"missingBucket\":false,\"missingBucketLabel\":\"Missing\",\"customLabel\":\"Field\"}}]}",
      "uiStateJSON": "{\"vis\":{\"params\":{\"sort\":{\"columnIndex\":null,\"direction\":null}}}}",
      "description": "",
      "version": 1,
      "kibanaSavedObjectMeta": {
        "searchSourceJSON": "{\"index\":\"5f276480-ff04-11e9-9f8f-4b15d29a5698\",\"query\":{\"language\":\"lucene\",\"query\":\"\"},\"filter\":[]}"
      }
    }
  }
]

middleware.py

from time import time as timer
from .utils import index_fn_timing
# If you run with celery/redis
# With redis/celery - this will increase the speed dramatically because it will be a fire and forget function
# from .tasks import index_fn_timing

# Some packages you don't want to track
exclude_modules = []


def timing_middleware(next, root, info, **kwargs):
    module = info.parent_type.__module__.split(".")[0]
    # We don't want something like __schema or __Type to be logged
    if module in exclude_modules or info.parent_type.name.startswith("__") or info.field_name.startswith("__"):
        return next(root, info, **kwargs)
    start = timer()
    return_value = next(root, info, **kwargs)
    index_fn_timing({
        "ts": timezone.now().isoformat(),
        "parent": info.parent_type.name,
        "field": info.field_name,
        "duration": timer() - start,
        "isDeprecated": info.parent_type.fields[info.field_name].is_deprecated
    })
    return return_value

requirements.txt

django==2.2
graphene==2.1.8
graphene-django==2.2.0
elasticsearch>=6.0.0,<7.0.0

settings.py

GRAPHENE = {
    'SCHEMA': ...,
    'MIDDLEWARE': [
        'path.to.timing_middleware',
        ...
    ]
}

ES_URL = "elasticsearch_url"

tasks.py

# With redis/celery
from myapp.utils import index_fn_timing as index_fn_timing_orig
@shared_task
def index_fn_timing_task(payload):
    index_fn_timing_orig(payload)

def index_fn_timing(payload):
    index_fn_timing_task.delay(payload)

utils.py

from django.utils import timezone
from elasticsearch import Elasticsearch
from django.conf import settings

es = Elasticsearch([settings.ES_URL], timeout=300)

def index_fn_timing(payload):
    try:
        now = timezone.now().strftime("%d-%m-%Y")
        es.index(index=f"gql-timing-{now}", doc_type="doc", body=payload)
    except Exception as e:
        pass # Handle exception