Importing `opentelemetry.exporter.otlp.proto.http.trace_exporter.OTLPSpanExporter` is slow

serkan-ozal commented 1 month ago

Describe your environment

Environment: AWS Lambda Python version: Python 3.9 SDK version: 1.26.0 API version: 1.26.0

What happened?

Initialization of the OTEL Python Lambda layer takes significant amount of time in the AWS Lambda environment because of module imports. When I have analyzed import timings, I have noticed that importing opentelemetry.exporter.otlp.proto.http.trace_exporter.OTLPSpanExporter is slow, because of the requests and opentelemetry.exporter.otlp.proto.common._internal imports as shown below.

I am not sure whether there is anything we can do about opentelemetry.exporter.otlp.proto.common._internal, but wanted to ask what we can do to improve for the requests module import latency.
Using OTLP JSON exporter (currently we don't have) in the Lambda layer to export to the local collector extension helps to cut about 100 ms coldstart delay (verified over a simple custom OTLP JSON exporter). But it still suffers from 230-240 ms request library import delay.
To get rid of the request library import delay, might switching to lower level one like urllib or urllib3 be an option?

Here is the portion of the module import timings related to opentelemetry.exporter.otlp.proto.http.trace_exporter.OTLPSpanExporter module import in a Lambda function with 512 MB memory. As you can see that

opentelemetry.exporter.otlp.proto.http.trace_exporter.OTLPSpanExporter module import took 367 ms
requests module import took 236 ms (64%)
opentelemetry.exporter.otlp.proto.common._internal took 110 ms (30%)

import time:       234 |        234 |               urllib3.packages
import time:      9887 |      10121 |             urllib3.packages.six
import time:       102 |      10223 |           urllib3.packages.six.moves
import time:      1274 |       1274 |             http
import time:      1486 |       2760 |           http.client
import time:       100 |      13082 |         urllib3.packages.six.moves.http_client
import time:      3783 |      16865 |       urllib3.exceptions
import time:       964 |        964 |       urllib3._version
import time:      2663 |       2663 |         urllib3._collections
import time:       239 |        239 |                 urllib3.contrib
import time:       424 |        424 |                 urllib3.contrib._appengine_environ
import time:      1722 |       1722 |                 urllib3.util.wait
import time:      1127 |       3510 |               urllib3.util.connection
import time:       136 |        136 |                 brotlicffi
import time:       102 |        102 |                 brotli
import time:       820 |       1057 |               urllib3.util.request
import time:       638 |        638 |               urllib3.util.response
import time:      3174 |       3174 |               urllib3.util.retry
import time:      1643 |       1643 |                   _hashlib
import time:       561 |        561 |                   _blake2
import time:       549 |       2753 |                 hashlib
import time:       438 |        438 |                 hmac
import time:     11452 |      11452 |                 urllib3.util.url
import time:      2092 |       2092 |                 urllib3.util.ssltransport
import time:      2627 |      19360 |               urllib3.util.ssl_
import time:      1189 |       1189 |               urllib3.util.timeout
import time:      1334 |      30259 |             urllib3.util
import time:       486 |      30745 |           urllib3.util.proxy
import time:      1063 |       1063 |           urllib3.util.ssl_match_hostname
import time:      3393 |      35200 |         urllib3.connection
import time:       147 |        147 |                 _winapi
import time:       102 |        102 |                 winreg
import time:       585 |        833 |               mimetypes
import time:      1559 |       2391 |             urllib3.fields
import time:      1572 |       3963 |           urllib3.filepost
import time:        46 |         46 |             urllib3.packages.six.moves.urllib
import time:        61 |        107 |           urllib3.packages.six.moves.urllib.parse
import time:      1056 |       5125 |         urllib3.request
import time:       285 |        285 |           brotlicffi
import time:       107 |        107 |           brotli
import time:      5976 |       6367 |         urllib3.response
import time:       473 |        473 |         urllib3.util.queue
import time:      5010 |      54836 |       urllib3.connectionpool
import time:      3482 |       3482 |       urllib3.poolmanager
import time:       144 |        144 |       urllib3_secure_extra
import time:      1756 |      78043 |     urllib3
import time:     10899 |      10899 |             charset_normalizer.constant
import time:       830 |        830 |                 unicodedata
import time:       475 |        475 |                 _multibytecodec
import time:      3171 |       4476 |               charset_normalizer.utils
import time:      4674 |       9149 |             charset_normalizer.md
import time:      2984 |       2984 |             charset_normalizer.models
import time:      2907 |      25938 |           charset_normalizer.cd
import time:      4592 |      30530 |         charset_normalizer.api
import time:       714 |        714 |         charset_normalizer.legacy
import time:       234 |        234 |         charset_normalizer.version
import time:       428 |        428 |           copy
import time:       376 |        376 |               urllib.response
import time:       493 |        869 |             urllib.error
import time:      5175 |       6043 |           urllib.request
import time:      3821 |      10291 |         http.cookiejar
import time:      1612 |       1612 |         http.cookies
import time:      2516 |      45896 |       requests.compat
import time:      2471 |      48366 |     requests.exceptions
import time:       144 |        144 |     chardet
import time:       958 |        958 |         idna.package_data
import time:     21829 |      21829 |           idna.idnadata
import time:       850 |        850 |           idna.intranges
import time:      4656 |      27335 |         idna.core
import time:      1106 |      29397 |       idna
import time:      1757 |      31154 |     requests.packages
import time:       846 |        846 |           certifi.core
import time:      1200 |       2046 |         certifi
import time:      1059 |       3105 |       requests.certs
import time:       256 |        256 |       requests.__version__
import time:       814 |        814 |       requests._internal_utils
import time:      3704 |       3704 |       requests.cookies
import time:      1935 |       1935 |       requests.structures
import time:       288 |        288 |           importlib.resources._itertools
import time:       501 |        789 |         importlib.resources.readers
import time:       315 |       1103 |       importlib.readers
import time:      6574 |      17488 |     requests.utils
import time:      2458 |       2458 |           requests.auth
import time:       568 |        568 |               stringprep
import time:       695 |       1262 |             encodings.idna
import time:       444 |        444 |             requests.hooks
import time:      1522 |       1522 |             requests.status_codes
import time:      7356 |      10583 |           requests.models
import time:       144 |        144 |             socks
import time:      3283 |       3426 |           urllib3.contrib.socks
import time:     37697 |      54163 |         requests.adapters
import time:      4248 |      58410 |       requests.sessions
import time:       722 |      59132 |     requests.api
import time:      2426 |     236751 |   requests
import time:       296 |        296 |       opentelemetry.exporter.otlp.proto.common.version
import time:      1171 |       1467 |     opentelemetry.exporter.otlp.proto.common
import time:      1405 |       1405 |           opentelemetry.proto
import time:       278 |       1683 |         opentelemetry.proto.common
import time:       233 |       1915 |       opentelemetry.proto.common.v1
import time:       654 |        654 |         google
import time:       955 |       1609 |       google.protobuf
import time:       324 |        324 |         google.protobuf.internal
import time:        71 |         71 |           google.protobuf.internal._api_implementation
import time:      2136 |       2136 |           google.protobuf.message
import time:      1292 |       1292 |           google.protobuf.internal.enum_type_wrapper
import time:        72 |         72 |           google.protobuf.enable_deterministic_proto_serialization
import time:      5843 |       9412 |         google.protobuf.internal.api_implementation
import time:      8047 |      17782 |       google.protobuf.descriptor
import time:      1208 |       1208 |         google.protobuf.descriptor_database
import time:      1137 |       1137 |         google.protobuf.text_encoding
import time:       939 |        939 |             encodings.raw_unicode_escape
import time:       480 |        480 |             encodings.unicode_escape
import time:       545 |        545 |                   _compat_pickle
import time:       876 |        876 |                   _pickle
import time:      1537 |       2957 |                 pickle
import time:      6628 |       9585 |               google.protobuf.internal.containers
import time:      4891 |       4891 |                 google.protobuf.internal.wire_format
import time:      5860 |      10751 |               google.protobuf.internal.encoder
import time:      7137 |      27472 |             google.protobuf.internal.decoder
import time:      1133 |       1133 |                 _ctypes
import time:       520 |        520 |                 ctypes._endian
import time:      1781 |       3432 |               ctypes
import time:      2780 |       6211 |             google.protobuf.internal.type_checkers
import time:      1656 |       1656 |             google.protobuf.unknown_fields
import time:     11588 |      48343 |           google.protobuf.text_format
import time:      1929 |       1929 |           google.protobuf.internal.extension_dict
import time:       394 |        394 |           google.protobuf.internal.message_listener
import time:      2312 |       2312 |             google.protobuf.internal.field_mask
import time:      4583 |       6895 |           google.protobuf.internal.well_known_types
import time:     10855 |      68414 |         google.protobuf.internal.python_message
import time:      8127 |      78884 |       google.protobuf.descriptor_pool
import time:       228 |        228 |           google.protobuf.pyext
import time:       373 |        373 |           google.protobuf.pyext.cpp_message
import time:      1260 |       1860 |         google.protobuf.message_factory
import time:      1063 |       1063 |         google.protobuf.symbol_database
import time:      1056 |       3978 |       google.protobuf.reflection
import time:      1586 |     105751 |     opentelemetry.proto.common.v1.common_pb2
import time:       554 |        554 |         opentelemetry.proto.resource
import time:       260 |        814 |       opentelemetry.proto.resource.v1
import time:      1300 |       2113 |     opentelemetry.proto.resource.v1.resource_pb2
import time:      1658 |     110987 |   opentelemetry.exporter.otlp.proto.common._internal
import time:       458 |        458 |             opentelemetry.proto.collector
import time:       274 |        731 |           opentelemetry.proto.collector.trace
import time:       242 |        972 |         opentelemetry.proto.collector.trace.v1
import time:       224 |        224 |           opentelemetry.proto.trace
import time:       275 |        498 |         opentelemetry.proto.trace.v1
import time:      1182 |       1182 |         opentelemetry.proto.trace.v1.trace_pb2
import time:      1248 |       3897 |       opentelemetry.proto.collector.trace.v1.trace_service_pb2
import time:      1693 |       5590 |     opentelemetry.exporter.otlp.proto.common._internal.trace_encoder
import time:      1114 |       6704 |   opentelemetry.exporter.otlp.proto.common.trace_encoder
import time:      4730 |       4730 |   opentelemetry.sdk.trace.export
import time:      3350 |       3350 |   opentelemetry.util.re
import time:      1821 |     367508 | opentelemetry.exporter.otlp.proto.http.trace_exporter

Steps to Reproduce

Set PYTHONPROFILEIMPORTTIME env var to true in the otel-instrument bash script of the OTEL Python Lambda layer
Import opentelemetry.exporter.otlp.proto.http.trace_exporter.OTLPSpanExporter module

Expected Result

-

Actual Result

-

Additional context

No response

Would you like to implement a fix?

None

xrmx commented 1 month ago

To get rid of the request library import delay, might switching to lower level one like urllib or urllib3 be an option?

Yeah, I think it would make sense to try prototyping one exporter using plain urllib3 instead of requests

xrmx commented 1 month ago

Let me add that the current implementation is tied to requests so eventually another one should be added instead of changing it to avoid breaking backwards compatibility.

serkan-ozal commented 1 month ago

@xrmx Maybe we can implement OTLP JSON span exporter on top of urrlib3 from the beginning. So, in the Lambda layer side, we can use it by default, so we will be able to get rid of both requests and opentelemetry.exporter.otlp.proto.common._internal import delays. Does that make sense?

xrmx commented 3 weeks ago

@xrmx Maybe we can implement OTLP JSON span exporter on top of urrlib3 from the beginning. So, in the Lambda layer side, we can use it by default, so we will be able to get rid of both requests and opentelemetry.exporter.otlp.proto.common._internal import delays. Does that make sense?

I don't know, that would be something to bring to the weekly call and ask for feedback maybe?

bhaskarbanerjee commented 3 weeks ago

Was choosing requests over urllib or urlib3 a conscious choice in opentelemetry? @xrmx @serkan-ozal

serkan-ozal commented 3 weeks ago

@bhaskarbanerjee replacing requests with urlib3 helped me to save about 150 milliseconds in a Lambda function with 512 MB memory limit. It is just one of the a few optimizations that needs to be done for reducing coldstart delays in Lambda.

Anyway, implementing lightweight versions of trace and metrics OTLP exporters to be used only by otel_wrapper.py in the opentelemetry-lambda repo makes more sense to me now. So probably, I will send PR to that repo, not here.

open-telemetry / opentelemetry-python