Merge pull request #6 from apollostack/add-tracer

merge in tracer changes from graphql-tools manually

package.json

@@ -33,8 +33,13 @@
   "homepage": "https://github.com/apollostack/apollo-proxy#readme",
   "dependencies": {
     "babel-polyfill": "^6.5.0",
-    "express-graphql": "^0.5.1",
-    "graphql-tools": "^0.3.10"
+    "graphql-tools": "^0.4.2",
+    "express-widgetizer": "^0.5.2",
+    "fs": "0.0.2",
+    "lodash": "^4.10.0",
+    "node-uuid": "^1.4.7",
+    "performance-now": "^0.2.0",
+    "request": "^2.72.0"
   },
   "devDependencies": {
     "babel-cli": "^6.6.5",
@@ -51,6 +56,7 @@
     "eslint-plugin-import": "^1.1.0",
     "express": "^4.13.4",
     "express3": "0.0.0",
+    "graphql": "^0.5.0",
     "istanbul": "1.0.0-alpha.2",
     "mocha": "^2.3.3",
     "multer": "^1.0.3",
@@ -59,6 +65,9 @@
     "supertest": "^1.0.1",
     "supertest-as-promised": "^2.0.2"
   },
+  "peerDependencies": {
+    "graphql": "^0.5.0"
+  },
   "eslintConfig": {
     "parser": "babel-eslint",
     "extends": [

src/apolloServer.js

@@ -3,9 +3,11 @@ import {
   buildSchemaFromTypeDefinitions,
   addErrorLoggingToSchema,
   addCatchUndefinedToSchema,
+  addResolveFunctionsToSchema,
+  addTracingToResolvers,
 } from 'graphql-tools';
 import { addMockFunctionsToSchema } from 'graphql-tools';
-import graphqlHTTP from 'express-graphql';
+import graphqlHTTP from 'express-widgetizer';
 import { GraphQLSchema, formatError } from 'graphql';
 
 // TODO this implementation could use a bit of refactoring.
@@ -20,8 +22,14 @@ export default function apolloServer(options, ...rest) {
     throw new Error(`apolloServer expects exactly one argument, got ${rest.length + 1}`);
   }
   // Resolve the Options to get OptionsData.
+
   return (req, res) => {
-    new Promise(resolve => {
+    let tracerLogger;
+
+    // TODO instrument ApolloServer's schema creation as well, so you know how long
+    // it takes. May be a big waste of time to recreate the schema for every request.
+
+    return new Promise(resolve => {
       resolve(typeof options === 'function' ? options(req) : options);
     }).then(optionsData => {
       // Assert that optionsData is in fact an Object.
@@ -42,25 +50,40 @@ export default function apolloServer(options, ...rest) {
         resolvers, // required if mocks is not false and schema is not GraphQLSchema
         connectors, // required if mocks is not false and schema is not GraphQLSchema
         logger,
+        tracer,
         printErrors,
         mocks = false,
         allowUndefinedInResolve = true,
         pretty, // pass through
         graphiql = false, // pass through
         validationRules, // pass through
-        context = {}, // pass through
+        context = {}, // pass through, but add tracer if applicable
         rootValue, // pass through
       } = optionsData;
 
       // would collide with formatError from graphql otherwise
       const formatErrorFn = optionsData.formatError;
 
+      // TODO: currently relies on the fact that start and end both exist
+      // and appear in the correct order and exactly once.
+      function processInterval(supertype, subtype, tstamp, intervalMap) {
+        if (subtype === 'start') {
+          // eslint-disable-next-line no-param-reassign
+          intervalMap[supertype] = tstamp;
+        }
+        if (subtype === 'end') {
+          // eslint-disable-next-line no-param-reassign
+          intervalMap[supertype] = tstamp - intervalMap[supertype];
+        }
+      }
+
       let executableSchema;
       if (mocks) {
         // TODO: mocks doesn't yet work with a normal GraphQL schema, but it should!
         // have to rewrite these functions
         const myMocks = mocks || {};
         executableSchema = buildSchemaFromTypeDefinitions(schema);
+        addResolveFunctionsToSchema(executableSchema, resolvers || {});
         addMockFunctionsToSchema({
           schema: executableSchema,
           mocks: myMocks,
@@ -97,6 +120,98 @@ export default function apolloServer(options, ...rest) {
           }
         }
       }
+
+      // Tracer-related stuff ------------------------------------------------
+
+      tracerLogger = { log: undefined, report: undefined };
+      if (tracer) {
+        tracerLogger = tracer.newLoggerInstance();
+        tracerLogger.log('request.info', {
+          headers: req.headers,
+          baseUrl: req.baseUrl,
+          originalUrl: req.originalUrl,
+          method: req.method,
+          httpVersion: req.httpVersion,
+          remoteAddr: req.connection.remoteAddress,
+        });
+        if (context.tracer) {
+          throw new Error('Property tracer on context already defined, cannot attach Tracer');
+        } else {
+          context.tracer = tracerLogger;
+        }
+        if (!executableSchema._apolloTracerApplied) {
+          addTracingToResolvers(executableSchema);
+        }
+      }
+
+      // TODO: move to proper place, make less fragile ...
+      // calculate timing information from events
+      function timings(events) {
+        const resolverDurations = [];
+        const intervalMap = {};
+
+        // split by event.type = [ , ]
+        events.forEach(e => {
+          const [supertype, subtype] = e.type.split('.');
+          switch (supertype) {
+            case 'request':
+            case 'parse':
+            case 'validation':
+            case 'execution':
+            case 'parseBody':
+            case 'parseParams':
+              processInterval(supertype, subtype, e.timestamp, intervalMap);
+              break;
+            case 'resolver':
+              if (subtype === 'end') {
+                resolverDurations.push({
+                  type: 'resolve',
+                  functionName: e.data.functionName,
+                  duration: e.timestamp - events[e.data.startEventId].timestamp,
+                });
+              }
+              break;
+            default:
+              console.error(`Unknown event type ${supertype}`);
+          }
+        });
+
+        const durations = [];
+        Object.keys(intervalMap).forEach((key) => {
+          durations.push({
+            type: key,
+            functionName: null,
+            duration: intervalMap[key],
+          });
+        });
+        return durations.concat(resolverDurations);
+      }
+
+      let extensionsFn = function extensionsFn() {
+        try {
+          return {
+            timings: timings(tracerLogger.report().events),
+            tracer: tracerLogger.report().events.map(e => ({
+              id: e.id,
+              type: e.type,
+              ts: e.timestamp,
+              data: e.data,
+            })).filter(x => x.type !== 'initialization'),
+          };
+        } catch (e) {
+          console.error(e);
+          console.error(e.stack);
+        }
+        return {};
+      };
+
+      // XXX ugly way of only passing extensionsFn when tracer is defined.
+      if (!tracer || req.headers['x-apollo-tracer-extension'] !== 'on') {
+        extensionsFn = undefined;
+      }
+
+      // end of Tracer related stuff -------------------------------------------
+
       // graphQLHTTPOptions
       return {
         schema: executableSchema,
@@ -106,6 +221,8 @@ export default function apolloServer(options, ...rest) {
         context,
         rootValue,
         graphiql,
+        logFn: tracerLogger.log,
+        extensionsFn,
       };
     }).then((graphqlHTTPOptions) => {
       return graphqlHTTP(graphqlHTTPOptions)(req, res);
@@ -119,6 +236,10 @@ export default function apolloServer(options, ...rest) {
       res
         .set('Content-Type', 'application/json')
         .send(JSON.stringify(result));
+      return result;
+    }).then(() => {
+      // send traces to Apollo Tracer
+      tracerLogger.submit();
     });
   };
 }