Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

capture/analyze application performance #384

Closed
edaniszewski opened this issue Apr 6, 2020 · 5 comments
Closed

capture/analyze application performance #384

edaniszewski opened this issue Apr 6, 2020 · 5 comments

Comments

@edaniszewski
Copy link
Contributor

After doing some quick comparisons of throughput/latency tests between synse v2 and synse v3, it appears that v3 has a bit higher latency. this could be due to a number of things, one of which being the added instrumentation for capturing application metrics, but that is just my current hypothesis and is likely not the sole cause.

This issue is to dive deeper into measuring application performance, making note of any bottlenecks/areas which may be optimized, etc. Even if the output of this is just confirming that the additional latency is solely from application metrics overhead, that is valuable information.

@edaniszewski
Copy link
Contributor Author

Putting this here for now.

Since it appeared that the latency for a v3 single device read increased from a v2 single device read, I decided to look into that first, using cProfile and graphviz, I came up with the following data

Synse v2

Profile output

         517 function calls (515 primitive calls) in 0.013 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        3    0.000    0.000    0.011    0.004 /usr/local/lib/python3.6/site-packages/synse/commands/read.py:13(read)
        2    0.000    0.000    0.010    0.005 /usr/local/lib/python3.6/site-packages/sanic/app.py:561(handle_request)
        2    0.000    0.000    0.010    0.005 /usr/local/lib/python3.6/site-packages/synse/validate.py:78(inner)
        2    0.000    0.000    0.010    0.005 /usr/local/lib/python3.6/site-packages/synse/routes/core.py:61(read_route)
        6    0.000    0.000    0.006    0.001 /usr/local/lib/python3.6/logging/__init__.py:1286(debug)
        4    0.000    0.000    0.005    0.001 /usr/local/lib/python3.6/logging/__init__.py:1421(_log)
        1    0.000    0.000    0.005    0.005 /usr/local/lib/python3.6/site-packages/synse/proto/client.py:187(read)
        4    0.000    0.000    0.003    0.001 /usr/local/lib/python3.6/logging/__init__.py:1446(handle)
        1    0.000    0.000    0.002    0.002 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:526(__call__)
        4    0.000    0.000    0.002    0.001 /usr/local/lib/python3.6/logging/__init__.py:1500(callHandlers)
        4    0.000    0.000    0.002    0.001 /usr/local/lib/python3.6/logging/__init__.py:1406(makeRecord)
        4    0.000    0.000    0.002    0.001 /usr/local/lib/python3.6/logging/__init__.py:852(handle)
        4    0.001    0.000    0.002    0.001 /usr/local/lib/python3.6/logging/__init__.py:251(__init__)
        4    0.000    0.000    0.002    0.000 /usr/local/lib/python3.6/logging/__init__.py:982(emit)
        3    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/synse/cache.py:121(get_device_info)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:744(drive)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:696(_run_channel_spin_thread)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:54(_enabled)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.6/site-packages/synse/proto/client.py:208(<listcomp>)
        2    0.000    0.000    0.001    0.001 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:346(__next__)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:318(_next)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/threading.py:263(wait)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/logging/__init__.py:829(format)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:38(_timeout)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:65(_plugins)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/logging/__init__.py:564(format)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.6/threading.py:828(start)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/asyncio/tasks.py:321(wait_for)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/synse/cache.py:186(get_device_info_cache)
        6    0.001    0.000    0.001    0.000 {method 'acquire' of '_thread.lock' objects}
        3    0.001    0.000    0.001    0.000 {method 'start_client_batch' of 'grpc._cython.cygrpc.Call' objects}
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.6/threading.py:533(wait)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:164(get)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/posixpath.py:144(basename)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.6/logging/__init__.py:971(flush)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/posixpath.py:121(splitext)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:1376(findCaller)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_common.py:114(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:757(__init__)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/bison/bison.py:95(get)
        5    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:239(__enter__)
      3/2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/bison/utils.py:98(get)
        4    0.000    0.000    0.000    0.000 {method '__enter__' of '_thread.RLock' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/asyncio/tasks.py:507(ensure_future)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/scheme/base_response.py:17(to_json)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/response.py:35(json)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:498(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/scheme/read.py:44(__init__)
        8    0.000    0.000    0.000    0.000 {built-in method time.monotonic}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/os.py:760(getenv)
        8    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:809(acquire)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:497(formatTime)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/scheme/read.py:53(format_readings)
        8    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:816(release)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/posixpath.py:52(normcase)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/posixpath.py:41(_get_sep)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/genericpath.py:117(_splitext)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:542(usesTime)
       20    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/_collections_abc.py:657(get)
        5    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:1230(current_thread)
        1    0.000    0.000    0.000    0.000 {built-in method _thread.start_new_thread}
        6    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:1544(isEnabledFor)
       18    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
        5    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:242(__exit__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/sanic/response.py:183(json)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/os.py:664(__getitem__)
       14    0.000    0.000    0.000    0.000 {built-in method builtins.hasattr}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:548(formatMessage)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/gettext.py:443(gettext)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:387(usesTime)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:157(<lambda>)
       12    0.000    0.000    0.000    0.000 {method 'rfind' of 'str' objects}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:120(getLevelName)
       12    0.000    0.000    0.000    0.000 {built-in method posix.fspath}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:417(_start_unary_request)
        2    0.000    0.000    0.000    0.000 {method 'create_task' of 'uvloop.loop.Loop' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/asyncio/tasks.py:316(_release_waiter)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/asyncio/events.py:682(get_event_loop)
      6/5    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/os.py:742(encode)
        9    0.000    0.000    0.000    0.000 {built-in method _thread.get_ident}
        5    0.000    0.000    0.000    0.000 {built-in method time.time}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:722(create)
        3    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/_weakrefset.py:81(add)
        8    0.000    0.000    0.000    0.000 {method 'write' of '_io.TextIOWrapper' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:408(__del__)
        4    0.000    0.000    0.000    0.000 {method 'flush' of '_io.TextIOWrapper' objects}
        8    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:705(filter)
        8    0.000    0.000    0.000    0.000 {method 'acquire' of '_thread.RLock' objects}
        8    0.000    0.000    0.000    0.000 {method 'release' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/response.py:9(_dumps)
        4    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:105(__init__)
        1    0.000    0.000    0.000    0.000 {method 'create_call' of 'grpc._cython.cygrpc.Channel' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/_weakrefset.py:38(_remove)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/asyncio/events.py:638(_get_running_loop)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:464(_build_key)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/asyncio/base_futures.py:23(isfuture)
        6    0.000    0.000    0.000    0.000 {built-in method posix.getpid}
        4    0.000    0.000    0.000    0.000 {built-in method time.localtime}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/aiocache/backends/memory.py:18(_get)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/sanic/response.py:122(__init__)
        6    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:1530(getEffectiveLevel)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:390(format)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/bison/utils.py:80(__contains__)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/asyncio/coroutines.py:270(iscoroutine)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/plugin.py:159(get_plugin)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:215(__init__)
        4    0.000    0.000    0.000    0.000 {built-in method time.strftime}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/logging/__init__.py:329(getMessage)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_common.py:93(serialize)
        2    0.000    0.000    0.000    0.000 {method 'done' of '_asyncio.Task' objects}
        4    0.000    0.000    0.000    0.000 {method 'find' of 'str' objects}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:1076(name)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/multiprocessing/process.py:146(name)
        4    0.000    0.000    0.000    0.000 {method 'count' of 'str' objects}
        4    0.000    0.000    0.000    0.000 {built-in method sys._getframe}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:62(_deadline)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:121(plugins)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/multiprocessing/process.py:35(current_process)
        4    0.000    0.000    0.000    0.000 {method 'add' of 'set' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/plugin.py:24(get)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/utils.py:19(composite)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/synse/plugin.py:142(__str__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:254(_is_owned)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/sanic/response.py:18(_encode_body)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:248(_release_save)
        3    0.000    0.000    0.000    0.000 {method 'encode' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:251(_acquire_restore)
        2    0.000    0.000    0.000    0.000 {method 'call_later' of 'uvloop.loop.Loop' objects}
        3    0.000    0.000    0.000    0.000 {built-in method _thread.allocate_lock}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_common.py:82(_transform)
        2    0.000    0.000    0.000    0.000 {method 'create_future' of 'uvloop.loop.Loop' objects}
        2    0.000    0.000    0.000    0.000 {method 'cancel' of 'uvloop.loop.TimerHandle' objects}
        2    0.000    0.000    0.000    0.000 {method 'set_result' of '_asyncio.Future' objects}
        1    0.000    0.000    0.000    0.000 {built-in method ujson.dumps}
        2    0.000    0.000    0.000    0.000 {method 'result' of '_asyncio.Task' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/aiocache/base.py:113(serializer)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/bison/bison.py:78(config)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:166(_event_handler)
        2    0.000    0.000    0.000    0.000 {method 'add_done_callback' of '_asyncio.Task' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:727(_newname)
        2    0.000    0.000    0.000    0.000 {method 'discard' of 'set' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/aiocache/serializers.py:37(loads)
        2    0.000    0.000    0.000    0.000 {method 'done' of '_asyncio.Future' objects}
        2    0.000    0.000    0.000    0.000 {method 'append' of 'collections.deque' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/bison/utils.py:48(__init__)
        1    0.000    0.000    0.000    0.000 {method '_acquire_restore' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 {method 'WhichOneof' of 'google.protobuf.pyext._message.CMessage' objects}
        1    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:74(RLock)
        1    0.000    0.000    0.000    0.000 {method '_release_save' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:506(is_set)
        1    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {function DotDict.__contains__ at 0x7f74b3f68c80}
        1    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:240(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/threading.py:1120(daemon)
        1    0.000    0.000    0.000    0.000 {method 'endswith' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method '_is_owned' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 {method 'release' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 {method '__enter__' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.6/site-packages/grpc/_channel.py:343(__iter__)

Call graph

v2-read

Synse v3

Profile output

         982 function calls in 0.021 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.000    0.000    0.021    0.010 /usr/local/lib/python3.8/site-packages/synse_server/cmd/read.py:150(read_device)
        4    0.000    0.000    0.014    0.003 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:113(_proxy_to_logger)
        4    0.000    0.000    0.014    0.003 /usr/local/lib/python3.8/site-packages/structlog/_base.py:165(_proxy_to_logger)
        1    0.000    0.000    0.013    0.013 /usr/local/lib/python3.8/site-packages/sanic/app.py:920(handle_request)
        1    0.000    0.000    0.013    0.013 /usr/local/lib/python3.8/site-packages/synse_server/api/http.py:436(read_device)
        3    0.000    0.000    0.010    0.003 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:64(debug)
        4    0.000    0.000    0.009    0.002 /usr/local/lib/python3.8/logging/__init__.py:1553(_log)
        2    0.000    0.000    0.008    0.004 /usr/local/lib/python3.8/site-packages/synse_server/cache.py:337(get_plugin)
        2    0.000    0.000    0.008    0.004 /usr/local/lib/python3.8/site-packages/synse_server/cache.py:222(get_device)
        4    0.000    0.000    0.007    0.002 /usr/local/lib/python3.8/logging/__init__.py:1412(debug)
        2    0.000    0.000    0.005    0.002 /usr/local/lib/python3.8/site-packages/synse_grpc/client.py:154(read)
        4    0.000    0.000    0.005    0.001 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:29(findCaller)
        4    0.001    0.000    0.005    0.001 /usr/local/lib/python3.8/site-packages/structlog/_base.py:116(_process_event)
        4    0.002    0.000    0.004    0.001 /usr/local/lib/python3.8/site-packages/structlog/_frames.py:28(_find_first_app_frame_and_name)
        1    0.000    0.000    0.004    0.004 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:70(info)
        1    0.000    0.000    0.003    0.003 /usr/local/lib/python3.8/site-packages/grpc/_interceptor.py:311(__call__)
        1    0.000    0.000    0.003    0.003 /usr/local/lib/python3.8/site-packages/synse_server/metrics.py:207(intercept_unary_stream)
        1    0.000    0.000    0.003    0.003 /usr/local/lib/python3.8/site-packages/grpc/_interceptor.py:322(continuation)
        1    0.000    0.000    0.002    0.002 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:924(__call__)
        1    0.000    0.000    0.002    0.002 /usr/local/lib/python3.8/logging/__init__.py:1424(info)
       96    0.002    0.000    0.002    0.000 /usr/local/lib/python3.8/site-packages/structlog/_frames.py:41(<genexpr>)
        4    0.000    0.000    0.002    0.001 /usr/local/lib/python3.8/logging/__init__.py:1579(handle)
        4    0.000    0.000    0.002    0.001 /usr/local/lib/python3.8/logging/__init__.py:1633(callHandlers)
        4    0.000    0.000    0.002    0.000 /usr/local/lib/python3.8/logging/__init__.py:1538(makeRecord)
        4    0.000    0.000    0.002    0.000 /usr/local/lib/python3.8/logging/__init__.py:937(handle)
        4    0.001    0.000    0.002    0.000 /usr/local/lib/python3.8/logging/__init__.py:284(__init__)
        1    0.000    0.000    0.002    0.002 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1149(create)
        4    0.000    0.000    0.002    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:98(__call__)
        4    0.000    0.000    0.002    0.000 /usr/local/lib/python3.8/logging/__init__.py:1069(emit)
        2    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/synse_server/metrics.py:251(wrap_stream_resp)
        2    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:415(__next__)
        4    0.000    0.000    0.001    0.000 {method 'join' of 'str' objects}
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:676(_next)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/threading.py:270(wait)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1126(_run_channel_spin_thread)
        1    0.001    0.001    0.001    0.001 {method 'integrated_call' of 'grpc._cython.cygrpc.Channel' objects}
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/synse_server/cmd/read.py:17(reading_to_dict)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:67(ordered_items)
       29    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:99(<genexpr>)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/synse_grpc/utils.py:15(to_dict)
       64    0.001    0.000    0.001    0.000 {method 'startswith' of 'str' objects}
        6    0.001    0.000    0.001    0.000 {method 'acquire' of '_thread.lock' objects}
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/logging/__init__.py:1058(flush)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/threading.py:834(start)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/grpc/_common.py:109(wait)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/logging/__init__.py:914(format)
        1    0.000    0.000    0.001    0.001 /usr/local/lib/python3.8/site-packages/grpc/_common.py:103(_wait_once)
        2    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:57(_enabled)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:149(__call__)
        4    0.000    0.000    0.001    0.000 /usr/local/lib/python3.8/logging/__init__.py:651(format)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:540(wait)
       51    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
       47    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
        3    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/prometheus_client/metrics.py:109(labels)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:40(_timeout)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/posixpath.py:117(splitext)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/posixpath.py:140(basename)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/contextvars.py:22(merge_contextvars)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:255(__call__)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/tasks.py:434(wait_for)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:69(_plugins)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:291(stamper_iso_utc)
       32    0.000    0.000    0.000    0.000 {built-in method builtins.any}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/utils.py:75(http_json_response)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/_config.py:357(__getattr__)
       25    0.000    0.000    0.000    0.000 {built-in method builtins.repr}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:139(MessageToDict)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:171(get)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:761(__init__)
        8    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:894(acquire)
       24    0.000    0.000    0.000    0.000 {method 'pop' of 'dict' objects}
        8    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:901(release)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/genericpath.py:121(_splitext)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:635(formatMessage)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:629(usesTime)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:709(_start_unary_request)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:207(_MessageToJsonObject)
        4    0.000    0.000    0.000    0.000 {method 'flush' of '_io.TextIOWrapper' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/tasks.py:653(ensure_future)
        6    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:249(__exit__)
        6    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:246(__enter__)
        4    0.000    0.000    0.000    0.000 {method 'sub' of 're.Pattern' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_interceptor.py:507(<lambda>)
       17    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
       15    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/prometheus_client/metrics.py:151(<genexpr>)
        1    0.000    0.000    0.000    0.000 {method 'operate' of 'grpc._cython.cygrpc.IntegratedCall' objects}
        5    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:1306(current_thread)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:218(_RegularMessageToJsonObject)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1377(unary_stream)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/sanic/response.py:217(json)
        8    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}
        8    0.000    0.000    0.000    0.000 {built-in method posix.fspath}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:387(add_log_level)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_common.py:90(serialize)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:362(filter_by_level)
        7    0.000    0.000    0.000    0.000 {built-in method time.time}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:434(format)
       12    0.000    0.000    0.000    0.000 {method 'rfind' of 'str' objects}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:418(add_logger_name)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:423(usesTime)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:377(__call__)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:119(getLevelName)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/contextvars.py:75(_get_context)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/processors.py:206(format_exc_info)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/posixpath.py:41(_get_sep)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/stdlib.py:318(__call__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/os.py:766(getenv)
        9    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
        1    0.000    0.000    0.000    0.000 {built-in method _thread.start_new_thread}
        9    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:1677(isEnabledFor)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:433(__del__)
        8    0.000    0.000    0.000    0.000 {method 'copy' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:95(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/_collections_abc.py:657(get)
        9    0.000    0.000    0.000    0.000 {built-in method _thread.get_ident}
        9    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
        4    0.000    0.000    0.000    0.000 {built-in method utcnow}
        8    0.000    0.000    0.000    0.000 {method 'acquire' of '_thread.RLock' objects}
        8    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:792(filter)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/bison/bison.py:100(get)
        8    0.000    0.000    0.000    0.000 {built-in method builtins.hasattr}
        8    0.000    0.000    0.000    0.000 {method 'release' of '_thread.RLock' objects}
        8    0.000    0.000    0.000    0.000 {built-in method builtins.len}
        4    0.000    0.000    0.000    0.000 {built-in method time.monotonic}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/prometheus_client/metrics.py:240(inc)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/os.py:670(__getitem__)
        1    0.000    0.000    0.000    0.000 {method 'create_task' of 'uvloop.loop.Loop' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/utils.py:49(_dumps)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:505(__init__)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/_weakrefset.py:81(add)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/tasks.py:429(_release_waiter)
        4    0.000    0.000    0.000    0.000 {method 'isoformat' of 'datetime.datetime' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:222(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/metrics.py:236(get_metadata)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/sanic/response.py:139(__init__)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/re.py:323(_subx)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/os.py:748(encode)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_common.py:66(encode)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/prometheus_client/metrics.py:529(observe)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/prometheus_client/values.py:18(inc)
        5    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.RLock' objects}
        5    0.000    0.000    0.000    0.000 {method '__enter__' of '_thread.RLock' objects}
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:431(_format)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/locks.py:102(__aexit__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/bison/utils.py:98(get)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/logging/__init__.py:360(getMessage)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:1031(name)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/multiprocessing/process.py:37(current_process)
        4    0.000    0.000    0.000    0.000 {built-in method posix.getpid}
        4    0.000    0.000    0.000    0.000 {method 'find' of 'str' objects}
        4    0.000    0.000    0.000    0.000 {built-in method sys._getframe}
        4    0.000    0.000    0.000    0.000 {method 'write' of '_io.TextIOWrapper' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_common.py:79(_transform)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/structlog/_config.py:322(finalized_bind)
        4    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/multiprocessing/process.py:189(name)
        4    0.000    0.000    0.000    0.000 {method 'get' of 'ContextVar' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:915(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:481(_build_key)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:84(_deadline)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/_collections_abc.py:672(keys)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:255(_release_save)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/plugin.py:380(__exit__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/backends/memory.py:18(_get)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:258(_acquire_restore)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/locks.py:96(__aenter__)
        3    0.000    0.000    0.000    0.000 {method 'encode' of 'str' objects}
        3    0.000    0.000    0.000    0.000 {built-in method _thread.allocate_lock}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:261(_is_owned)
        1    0.000    0.000    0.000    0.000 <string>:1(__new__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/sanic/response.py:25(_encode_body)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/plugin.py:60(get)
        3    0.000    0.000    0.000    0.000 {method 'add' of 'set' objects}
        3    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1169(<genexpr>)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:1110(daemon)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1099(__new__)
        1    0.000    0.000    0.000    0.000 {method 'add_done_callback' of '_asyncio.Task' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/_weakrefset.py:38(_remove)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/locks.py:214(release)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:753(_determine_deadline)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:283(_FieldToJsonObject)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:177(_IsMapEntry)
        1    0.000    0.000    0.000    0.000 {method 'call_later' of 'uvloop.loop.Loop' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:691(_response_ready)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:162(_event_handler)
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:128(plugins)
        1    0.000    0.000    0.000    0.000 {built-in method ujson.dumps}
        2    0.000    0.000    0.000    0.000 {built-in method __new__ of type object at 0x7f4d63270980}
        2    0.000    0.000    0.000    0.000 {method 'lower' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {method 'append' of 'collections.deque' objects}
        2    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:513(is_set)
        1    0.000    0.000    0.000    0.000 {method 'SerializeToString' of 'google.protobuf.pyext._message.CMessage' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:365(__init__)
        1    0.000    0.000    0.000    0.000 {method 'ListFields' of 'google.protobuf.pyext._message.CMessage' objects}
        1    0.000    0.000    0.000    0.000 {method 'WhichOneof' of 'google.protobuf.pyext._message.CMessage' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/_collections_abc.py:719(__iter__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:382(_IsWrapperMessage)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/google/protobuf/json_format.py:186(__init__)
        1    0.000    0.000    0.000    0.000 {method '_acquire_restore' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 {method 'set_result' of '_asyncio.Future' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_interceptor.py:54(_unwrap_client_call_details)
        1    0.000    0.000    0.000    0.000 {method 'cancel' of 'uvloop.loop.TimerHandle' objects}
        1    0.000    0.000    0.000    0.000 {grpc._cython.cygrpc.get_fork_epoch}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:1177(_make_invoke_excepthook)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/coroutines.py:177(iscoroutine)
        1    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:81(RLock)
        1    0.000    0.000    0.000    0.000 {method '_release_save' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1146(_channel_managed_call_management)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/_collections_abc.py:698(__init__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/plugin.py:377(__enter__)
        1    0.000    0.000    0.000    0.000 {method 'create_future' of 'uvloop.loop.Loop' objects}
        1    0.000    0.000    0.000    0.000 {built-in method _asyncio.get_running_loop}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/synse_server/plugin.py:480(mark_active)
        1    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:1095(daemon)
        1    0.000    0.000    0.000    0.000 {method 'endswith' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {grpc._cython.cygrpc.build_census_context}
        1    0.000    0.000    0.000    0.000 {method '__enter__' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 {method '_is_owned' of '_thread.RLock' objects}
        1    0.000    0.000    0.000    0.000 {method 'release' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/base.py:120(serializer)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/locks.py:231(_wake_up_first)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/aiocache/serializers/serializers.py:59(loads)
        1    0.000    0.000    0.000    0.000 {method 'result' of '_asyncio.Task' objects}
        1    0.000    0.000    0.000    0.000 {method 'done' of '_asyncio.Task' objects}
        1    0.000    0.000    0.000    0.000 {method 'done' of '_asyncio.Future' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/asyncio/locks.py:182(acquire)
        1    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.lock' objects}
        1    0.000    0.000    0.000    0.000 {method 'count' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:409(__iter__)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/threading.py:734(_newname)
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_channel.py:1103(with_wait_for_ready)
        1    0.000    0.000    0.000    0.000 {grpc._cython.cygrpc.get_deadline_from_context}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/grpc/_compression.py:42(augment_metadata)
        1    0.000    0.000    0.000    0.000 {method 'discard' of 'set' objects}
        1    0.000    0.000    0.000    0.000 /usr/local/lib/python3.8/site-packages/bison/bison.py:83(config)

Call graph

read-device-graph

@edaniszewski
Copy link
Contributor Author

Initial analysis suggests that structlog has a large impact on performance based on how it is being used here. Its also interesting to see that the number of function calls nearly doubled from v2 to v3.

@edaniszewski
Copy link
Contributor Author

Confirmed that structlog has a large impact here. I did some more testing on three variations of the code:

  1. As-is, using structlog calls
  2. Modified, replacing structlog calls with calls to the standard logger
  3. Modified, stripping out all logging on the call path.

The abridged results are as follows:

  • structlog: 1278 function calls in 0.027 seconds
  • standard logger: 757 function calls in 0.018 seconds
  • no logging: 503 function calls in 0.013 seconds

The question around this is whether this is acceptable or not. Obviously lower latency is better, but I feel like the value structlog brings in being able to associate request IDs or other bits of data for the lifecycle of the request is pretty valuable moving forward. We could look around and see if there are any other structured logging libraries and how they perform if this is an issue. I haven't seen many others with the same capabilities as structlog. Another option could be to write our own, but that feels like overkill.

At least for the read request, there is not a lot of room for micro-optimizations otherwise, as the majority of the remaining execution time is around the grpc network call.

@edaniszewski
Copy link
Contributor Author

I did some brief analysis on some of the other logging solutions out there to see how they compare to structlog, regarding performance, results are below:

0. std logger   18.17821265299999
1. logzero      23.810914749
2. logbook      31.224336361
3. structlog    47.88168331099999
4. loguru       71.99209493000001

these results reflect the time (in seconds) it takes to execute 1000000 calls to log.debug("test benchmark"). granted, its a simple test that does not fully exercise other factors (logging levels, complex messages, etc).

The comparisons here aren't necessarily fair, because of the 5 packages listed above, only structlog and loguru have structured logging capabilities built-in, so its not as simple as just replacing structlog with one of the better performing libraries at this moment.

@edaniszewski
Copy link
Contributor Author

I think that the data collection and results of this are sufficient to close this issue.

To summarize, it appears that extra latency is being added in fulfilling requests for synse v3 because of the overhead brought on by structlog.

At this time, it feels like the value that structlog affords outweighs the overhead that it brings. This may change in the future and we may eventually want to swap out the logging backend, but that doesn't feel necessary in the near future.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant