GraphQL Tracer

README.md

Scope

Tracking performance for GraphQL in development is quite hard.

I'm using the Apollo Tracing format here. Unfortunately there isn't a good viewer for the information from there. It also doesn't include SQL/Cache information.

Features:

• Viewer for tracing information
• Store tracing information on disk, for future reference
• Attach SQL queries to resolver information
• Attach cache hit/miss in to resolver information
• Enabled via ENV variable

Will be moved to its own ruby gem when ready.

Considered an experiment for now 🚧

Known issues

• Missing tests
• SQL Cache is not included in result
• SQL from promises is not included in result
• Code is MVP

Screenshots

Notes for Deployment

None

initializers_kitty_trace.rb

# frozen_string_literal: true

KittyTrace.subscribe

kitty_trace.rb

# frozen_string_literal: true

require 'graphql'

module KittyTrace
  extend self

  def use(schema_definition)
    schema_definition.instrument(:query, Tracer)
    schema_definition.instrument(:field, Tracer)
  end

  def time_diff(start_time, end_time)
    ((end_time.to_f - start_time.to_f) * 1e9).to_i
  end

  def subscribe # rubocop:disable Metrics/MethodLength
    ActiveSupport::Notifications.subscribe('sql.active_record') do |_name, start, ending, _transaction_id, payload|
      if payload[:name] != 'SCHEMA'
        KittyTrace::Current.record_io(
          sql: payload[:sql],
          duration: KittyTrace.time_diff(start, ending),
          name: payload[:name],
          line: payload[:line],
          filename: payload[:filename],
          method: payload[:method],
        )
      end
    end

    ActiveSupport::Notifications.subscribe('cache_read.active_support') do |_name, start, ending, _transaction_id, payload|
      KittyTrace::Current.record_io(
        cacheKey: payload[:key],
        cacheHit: payload[:hit],
        duration: KittyTrace.time_diff(start, ending),
        name: payload[:name],
        line: payload[:line],
        filename: payload[:filename],
        method: payload[:method],
      )
    end
  end
end

class KittyTrace::Current < ActiveSupport::CurrentAttributes
  attribute :io

  def record_io(recording)
    io << recording unless io.nil?
  end
end

# def log(message)
#   Rails.logger.info ActiveSupport::LogSubscriber.new.send(:color, "LOG: #{message}", :red)
# end

module KittyTrace::Tracer
  extend self

  KEY = :kitty_trace

  def before_query(query)
    query.context[KEY] = {
      'start_time' => Time.current,
      'resolvers' => [],
    }
  end

  def after_query(query)
    result = query.result
    return if result.nil? || result.to_h.nil?

    end_time = Time.current

    write_key = "#{end_time.to_i}_#{(query.operation_name || 'Query')}_#{SecureRandom.hex(4)}"
    trace = {
      'version' => 1,
      'startTime' => query.context[KEY]['start_time'].strftime('%FT%T.%3NZ'),
      'endTime' => end_time.strftime('%FT%T.%3NZ'),
      'duration' => KittyTrace.time_diff(query.context[KEY]['start_time'], end_time),
      'execution' => {
        'resolvers' => query.context[KEY]['resolvers'],
      },
    }

    KittyTrace::Storage.write(write_key, trace)
  end

  def instrument(type, field)
    old_resolve_proc = field.resolve_proc

    new_resolve_proc = lambda do |obj, args, context|
      io = []

      # NOTE(rstankov): Because of graphql-batch and promises don't reset this variable after sync resolve
      # Passing io by reference will record the io in the last Promise field
      KittyTrace::Current.io = io

      start_time = Time.current
      result = old_resolve_proc.call(obj, args, context)
      end_time = Time.current

      context[KEY]['resolvers'] << {
        'path' => context.path,
        'parentType' => type.name,
        'fieldName' => field.name,
        'returnType' => field.type.to_s,
        'startOffset' => KittyTrace.time_diff(context[KEY]['start_time'], start_time),
        'duration' => KittyTrace.time_diff(start_time, end_time),
        'io' => io,
      }

      result
    end

    field.redefine { resolve(new_resolve_proc) }
  end
end

module KittyTrace::Config
  extend self

  def file_limit
    20
  end
end

module KittyTrace
  module Storage
    extend self

    def write(key, value)
      FileUtils.mkdir_p dir_path
      json_file = dir_path.join("#{key}.json")
      File.open(json_file, 'wb') { |file| file.write(value.to_json) }
      maintain_limited_number_of_files(KittyTrace::Config.file_limit)
    end

    def files
      Dir["#{dir_path}/*.json"].map { |file_name| Record.new(file_name) }.sort_by(&:time).reverse
    end

    def read(key)
      key = File.basename(key, '.json')
      json_file = dir_path.join("#{key}.json")

      File.read(json_file)
    end

    private

    def maintain_limited_number_of_files(size)
      files = Dir["#{dir_path}/*.json"].sort_by { |f| -file_ctime(f) }
      (files[size..-1] || []).each do |file|
        FileUtils.rm_f(file)
      end
    end

    def file_ctime(file)
      File.stat(file).ctime.to_i
    rescue Errno::ENOENT
      0
    end

    def dir_path
      Rails.root.join('tmp', 'data', 'kitty_trace')
    end

    class Record
      attr_reader :id, :time, :operation_name

      def initialize(file_name)
        @id = File.basename(file_name, '.json')
        @time, @operation_name = id.split('_')
      end

      def as_json(_)
        {
          id: id,
          time: time,
          operationName: operation_name,
        }
      end
    end
  end
end

module KittyTrace
  class RecordsController < ActionController::API
    def index
      render json: KittyTrace::Storage.files
    end

    def show
      render json: KittyTrace::Storage.read(params[:id])
    rescue Errno::ENOENT
      render json: nil
    end
  end
end

kitty_trace_spec.rb

# frozen_string_literal: true

describe KittyTrace do
  def execute_query(query)
    trace_key = nil
    trace = nil

    allow(KittyTrace::Storage).to receive(:write) do |key, value|
      trace_key = key
      trace = value
    end

    result = StacksSchema.execute(query, variables: {}, context: {})

    OpenStruct.new(
      data: result.to_h['data'],
      trace_key: trace_key,
      trace: trace,
    )
  end

  describe 'tracing' do
    let(:product) { create :profile, slug: 'rstankov' }

    it 'doesnt interfere with proper query result' do
      result = execute_query <<-GRAPHQL
      query {
        profile(slug:"#{product.slug}") {
          id
        }
      }
      GRAPHQL

      expect(result.data).to eq(
        'profile' => {
          'id' => product.id.to_s,
        },
      )
    end

    it 'is saved into file with proper name' do
      result = execute_query <<-GRAPHQL
      query QueryName {
        profile(slug:"#{product.slug}") {
          id
        }
      }
      GRAPHQL

      expect(result.trace_key).to match(/^[\d]+_QueryName_[\w]+$/)
    end

    it 'include general query information' do
      result = execute_query <<-GRAPHQL
      query {
        profile(slug:"#{product.slug}") {
          id
        }
      }
      GRAPHQL

      trace = result.trace

      expect(trace).to include(
        'version' => 1,
        'startTime' => match(/^[\d]{4}-[\d]{2}-[\d]{2}T[\d]{2}:[\d]{2}:[\d]{2}\.[\w]+$/),
        'endTime' => match(/^[\d]{4}-[\d]{2}-[\d]{2}T[\d]{2}:[\d]{2}:[\d]{2}\.[\w]+$/),
        'duration' => be_kind_of(Integer),
        'execution' => {
          'resolvers' => be_kind_of(Array),
        },
      )
    end

    it 'includes detailed information about each resulver' do
      result = execute_query <<-GRAPHQL
      query {
        profile(slug:"#{product.slug}") {
          id
          name
        }
      }
      GRAPHQL

      trace = result.trace

      expect(trace).to include(
        'version' => 1,
        'startTime' => match(/^[\d]{4}-[\d]{2}-[\d]{2}T[\d]{2}:[\d]{2}:[\d]{2}\.[\w]+$/),
        'endTime' => match(/^[\d]{4}-[\d]{2}-[\d]{2}T[\d]{2}:[\d]{2}:[\d]{2}\.[\w]+$/),
        'duration' => be_kind_of(Integer),
        'execution' => {
          'resolvers' => be_kind_of(Array),
        },
      )

      expect(trace['execution']['resolvers'].size).to eq 3

      expect(trace['execution']['resolvers'][0]).to include(
        'path' => ['profile'],
        'parentType' => 'Query',
        'fieldName' => 'profile',
        'returnType' => 'Profile',
        'startOffset' => be_kind_of(Integer),
        'duration' => be_kind_of(Integer),
        'io' => [{
          sql: "SELECT \"profiles\".* FROM \"profiles\" WHERE \"profiles\".\"trashed_at\" IS NULL AND \"profiles\".\"slug\" = 'rstankov' LIMIT 1 /*application:Stacks,extra:profile*/", # rubocop:disable Metrics/LineLength
          duration: be_kind_of(Integer),
          name: 'Profile Load',
          line: nil,
          filename: nil,
          method: nil,
        }],
      )

      expect(trace['execution']['resolvers'][1]).to include(
        'path' => %w(profile id),
        'parentType' => 'Profile',
        'fieldName' => 'id',
        'returnType' => 'String!',
        'startOffset' => be_kind_of(Integer),
        'duration' => be_kind_of(Integer),
        'io' => [],
      )

      expect(trace['execution']['resolvers'][2]).to include(
        'path' => %w(profile name),
        'parentType' => 'Profile',
        'fieldName' => 'name',
        'returnType' => 'String!',
        'startOffset' => be_kind_of(Integer),
        'duration' => be_kind_of(Integer),
        'io' => [],
      )
    end
  end
end

routes.rb

    get '/admin/graphql-tracing' => 'kitty_trace/records#index'
    get '/admin/graphql-tracing/:id' => 'kitty_trace/records#show'

TracingPage.tsx

import * as React from 'react';
import styles from './styles.css';
import { useFetch } from './utils';
import TracingTable from './TracingTable';

export default function Tracer({ traceId }: { traceId?: string }) {
  const response = useFetch('/admin/graphql-tracing/');

  if (!response.data) {
    return null;
  }

  return (
    <div className={styles.container}>
      <ul className={styles.menu}>
        {response.data.map((record: any) => (
          <li key={record.id}>
            <a href={`?traceId=${record.id}`}>
              {record.id === traceId
                ? `[${record.operationName}]`
                : record.operationName}
            </a>
          </li>
        ))}
      </ul>
      {traceId && <LoadTrace traceId={traceId} />}
    </div>
  );
}

Tracer.getInitialProps = async (context: { query: any }) => {
  return { traceId: (context.query || {}).traceId };
};

function LoadTrace({ traceId }: { traceId: string }) {
  const response = useFetch(`/admin/graphql-tracing/${traceId}`);

  if (!response.data) {
    return null;
  }

  return <TracingTable tracing={response.data} />;
}

TracingTable.css

.container {
  display: flex;
  flex-direction: row;
  align-items: flex-start;
  margin: $spacing-large auto;
  max-width: 1000px;
  width: 100%;
}

.menu {
  margin-right: $spacing-medium;
  padding: $spacing-small;
  border-radius: $radius;
  border: 1px solid $line;
}

.table {
  flex: 1;
}

.row {
  display: flex;
  flex-direction: row;
  position: relative;
  font-size: 12px;
  padding-right: 25px;
  color: $black;

  &:hover {
    background: rgba(100, 100, 100, 0.1);
  }
}

.name {
  width: 230px;
  margin-right: $spacing-small;
}

.barContainer {
  margin-top: 5px;
  position: relative;
  height: 10px;
  width: 400px;
  background: $background-grey;
}

.bar {
  position: absolute;
  top: 0;
  bottom: 0;
  background: $black;
}

.duration {
  font-size: 10px;
  color: $dark-grey;
  margin-left: $spacing-medium;
}

.ioButton {
  background: $black;
  color: $white;
  border-radius: 50%;
  position: absolute;
  right: 0;
  width: 18px;
  height: 18px;
  text-align: center;
  cursor: pointer;
}

ol {
  margin: $spacing-small 0 $spacing-medium $spacing-medium;
  padding: $spacing-small $spacing-small $spacing-large $spacing-large;
  border-radius: $radius;
  border: 1px solid $line;
}

.small {
  font-size: 10px;
  color: $dark-grey;
}

TracingTable.tsx

import * as React from 'react';
import styles from './styles.css';
import { set, get } from 'lodash';

function TracingTable({ tracing }: { tracing: any }) {
  return (
    <div className={styles.table}>
      <InfoRow duration={tracing.duration} />
      {group(tracing.execution.resolvers).map((res: any, i: any) => (
        <TracingRow key={i} data={res} durationTotal={tracing.duration} />
      ))}
      <InfoRow duration={tracing.duration} />
    </div>
  );
}

export default React.memo(TracingTable);

interface ITraceData {
  path: string[];
  startOffsets: number[];
  durations: number[];
  io: any[];
  durationSum: number;
  count: number;
  fieldName: string;
}

function group(array: any[]): ITraceData[] {
  const result = array.reduce(
    (acc, tracing) => {
      const key =
        tracing.path
          .filter((field: number | string) => typeof field === 'string')
          .join('.') + '.__trace';

      let data = get(acc, key);

      if (!data) {
        data = {
          path: tracing.path,
          startOffsets: [],
          durations: [],
          io: [],
          durationSum: 0,
          count: 0,
          fieldName: tracing.fieldName,
        };
      }

      data.startOffsets.push(tracing.startOffset);
      data.durations.push(tracing.duration);
      data.io = data.io.concat(tracing.io);
      data.durationSum += tracing.duration;
      data.count += 1;

      set(acc, key, data);

      return acc;
    },
    {} as any,
  );

  return flatten(result);
}

function flatten(result: any[], array = []): any[] {
  return Object.values(result).reduce((acc, object) => {
    const { __trace: trace, ...others } = object;

    acc.push(trace);

    return flatten(others, acc);
  }, array);
}

function InfoRow({ duration }: { duration: number }) {
  return (
    <div className={styles.row}>
      <span className={styles.name}>Request</span>
      <div
        className={styles.barContainer}
        style={{ width: durationWidth(duration) }}>
        <Bar startOffset={0} duration={duration} />
      </div>
      <Duration duration={duration} />
    </div>
  );
}

interface ITracingRowProps {
  durationTotal: number;
  data: ITraceData;
}

export const TracingRow = ({ durationTotal, data }: ITracingRowProps) => {
  const [isOpen, setIsOpen] = React.useState(false);

  const usedFieldName = data.path.slice(-1)[0];

  return (
    <React.Fragment>
      <div className={styles.row}>
        <span
          className={styles.name}
          title={data.path.join('.')}
          style={{ paddingLeft: data.path.length * 10 }}>
          {usedFieldName === data.fieldName ? (
            data.fieldName
          ) : (
            <React.Fragment>
              {usedFieldName}
              <Small> /{data.fieldName}/</Small>
            </React.Fragment>
          )}
          {data.count > 1 && <Small> ({data.count})</Small>}
        </span>
        <div
          className={styles.barContainer}
          style={{ width: durationWidth(durationTotal) }}>
          {data.startOffsets.map((startOffset, i) => (
            <Bar
              key={i}
              startOffset={startOffset}
              duration={data.durations[i]}
            />
          ))}
        </div>
        <Duration duration={data.durationSum} />
        {data.io.length > 0 && (
          <span className={styles.ioButton} onClick={() => setIsOpen(!isOpen)}>
            {data.io.length}
          </span>
        )}
      </div>
      {isOpen && (
        <ol>
          {data.io.map((item, i) => (
            <li key={i}>
              <small>
                {item.sql && <code>{clearComments(item.sql)}</code>}
                {item.cacheKey && (
                  <code>
                    CACHE
                    {item.cacheHit ? ' HIT' : ' MISS'} => {item.cacheKey}
                  </code>
                )}
              </small>
              <Duration duration={item.duration} />
            </li>
          ))}
        </ol>
      )}
    </React.Fragment>
  );
};

function Small({ children }: { children: React.ReactNode }) {
  return <small className={styles.small}>{children}</small>;
}

const FACTOR = 1000 * 1000;

function durationWidth(duration: number) {
  return Math.max(Math.round(duration / FACTOR), 1);
}

function Bar({
  duration,
  startOffset,
}: {
  duration: number;
  startOffset: number;
}) {
  return (
    <span
      className={styles.bar}
      style={{
        width: durationWidth(duration),
        left: durationWidth(startOffset),
      }}
    />
  );
}

function Duration({ duration }: { duration: number }) {
  return <span className={styles.duration}>{printDuration(duration)}</span>;
}

function printDuration(nanoSeconds: number) {
  const microSeconds = Math.round(nanoSeconds / 1000);
  if (microSeconds > 1000) {
    return `${Math.round(microSeconds / 1000)} ms`;
  }

  return `${microSeconds} µs`;
}

function clearComments(sql: string) {
  return sql.replace(/\/\*.*\*\//g, '');
}

TracingTable_utils.tsx

import * as React from 'react';

const dataFetchReducer = (state: any, action: any) => {
  switch (action.type) {
    case 'FETCH_INIT':
      return {
        ...state,
        isLoading: true,
        isError: false,
      };
    case 'FETCH_SUCCESS':
      return {
        ...state,
        isLoading: false,
        isError: false,
        data: action.payload,
      };
    case 'FETCH_FAILURE':
      return {
        ...state,
        isLoading: false,
        isError: true,
      };
    default:
      throw new Error();
  }
};

export function useFetch(url: string) {
  const [state, dispatch] = React.useReducer(dataFetchReducer, {
    isLoading: false,
    isError: false,
    data: null,
  });

  React.useEffect(() => {
    let didCancel = false;

    const fetchData = async () => {
      dispatch({ type: 'FETCH_INIT' });

      try {
        const result = await fetch(url);
        const data = await result.json();

        if (!didCancel) {
          dispatch({ type: 'FETCH_SUCCESS', payload: data });
        }
      } catch (error) {
        if (!didCancel) {
          dispatch({ type: 'FETCH_FAILURE' });
        }
      }
    };

    fetchData();

    return () => {
      didCancel = true;
    };
  }, [url]);

  return state;
}