server.py

#!/usr/bin/env python

from __future__ import absolute_import, division, print_function, \
    unicode_literals

from concurrent.futures import ThreadPoolExecutor
from ddtrace import tracer
from ddtrace.contrib.tornado import trace_app
from random import uniform
from time import sleep
from tornado.concurrent import run_on_executor
from tornado.gen import coroutine, sleep as gen_sleep
from tornado.ioloop import IOLoop
from tornado.web import Application, RequestHandler
import logging


class Client(object):

    # This span won't have a parent
    @tracer.wrap('client.make_request')
    def make_request(self):
        sleep(1)
        return 'request'


class MainHandler(RequestHandler):
    executor = ThreadPoolExecutor(max_workers=3)

    # This will be outside the future and have the right parent, but only time
    # the creation of the future object and thus have 0s elapsed.
    @tracer.wrap('do_stuff_wrong')
    @run_on_executor
    def do_stuff_wrong(self):
        sleep(1)
        return 'wrong'

    @run_on_executor
    # This will be inside the future and time the method correctly, but won't
    # be a child of the parent
    @tracer.wrap('do_stuff_right')
    def do_stuff_right(self):
        sleep(1)
        return 'right'

    # Again, right parent, but timing the future not the method run
    @tracer.wrap('do_request')
    @run_on_executor
    def do_request(self):
        sleep(0.5)
        return Client().make_request()

    @run_on_executor
    def do_sleep(self):
        # These spans won't have a parent
        with tracer.trace('do_sleep'):
            sleep(uniform(0.5, 1.5))
            return 'slept'

    @coroutine
    def get(self):
        yield gen_sleep(0.25)

        results = []

        result = yield self.do_stuff_wrong()
        results.append(result)

        result = yield self.do_stuff_right()
        results.append(result)

        result = yield self.do_request()
        results.append(result)

        # This span will have the right parent and duration
        with tracer.trace('starting_sleeps'):
            sleeps = [self.do_sleep() for i in range(8)]
            with tracer.trace('number_crunching'):
                results.append(42 * 42)
            sleeps = yield sleeps
            results += sleeps

        self.write('Hello, world: {}'.format(results))


def get_app():
    return Application([
        (r'/', MainHandler),
    ], autoreload=True)


if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    app = get_app()
    tracer.debug_logging = True
    trace_app(app, tracer, service='tracing-test')
    app.listen(8888, address='127.0.0.1')
    IOLoop.current().start()

# Expected trace would look something like:
# - tornado.request (6s-9s)
#   - do_stuff_wrong (1s)
#   - do_stuff_right (1s)
#   - do_request (1.5s)
#     - client.make_request (1s)
#   - starting_sleeps (1.5s-4.5s)
#     [number_crunching (0s), do_sleep (0.5-1.5s), do_sleep (0.5-1.5s), do_sleep (0.5-1.5s)]
#     [do_sleep (0.5-1.5s), do_sleep (0.5-1.5s), do_sleep (0.5-1.5s)]
#     [do_sleep (0.5-1.5s), do_sleep (0.5-1.5s)]

# Resulting trace
# - do_stuff_right (1s)
# - client.make_request (1s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - do_sleep (0.5-1.5s)
# - tornado.request (6s-9s)
#   - do_stuff_wrong (0s)
#   - do_request (0s)
#   - starting_sleeps (1.5s-4.5s)
#     - number_crunching (0s)

# requirements.txt:
# futures==3.0.5
# tornado==4.4.1
# -e git+ssh://git@github.com/datadog/dd-trace-py.git@palazzem/tornado-support#egg=dd-trace-py