Skip to content

fix(profiling): stop calling logger from lock profiler [backport 3.4] #13152

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

Merged
merged 3 commits into from
Apr 16, 2025

Conversation

github-actions[bot]
Copy link
Contributor

@github-actions github-actions bot commented Apr 9, 2025

Backport 29ab7d8 from #13147 to 3.4.

        try:
            del self._self_acquired_at
        except AttributeError:
            LOG.debug("Failed to delete _self_acquired_at")

Above code resulted in an infinite recursion from a customer environment, by calling LOG.debug(). This PR removes logger from the lock profiler as logging any information from lock profiler to customer environment caused more harm than benefit.

We don't always set the _self_acquired_at attribute when acquire() is called. It's set only when the acquire() is sampled. And in the except block above, the call to LOG.debug() leads to acquire()/release() calls. Then if a subsequent acquire() was not captured, then it will be calling LOG.debug() again from release(), leading to an infinite recursion.

  1. File /usr/local/lib/python3.11/logging/__init__.py, line 1477, in debug
            self._log(DEBUG, msg, args, **kwargs)
  1. File /usr/local/lib/python3.11/logging/__init__.py, line 1632, in _log
        record = self.makeRecord(self.name, level, fn, lno, msg, args,
                                 exc_info, func, extra, sinfo)
  1. File /code/.venv/lib/python3.11/site-packages/ddtrace/contrib/internal/logging/patch.py, line 70, in _w_makeRecord
    record = func(*args, **kwargs)
  1. File /usr/local/lib/python3.11/logging/__init__.py, line 1601, in makeRecord
        rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
                             sinfo)
  1. File /usr/local/lib/python3.11/logging/__init__.py, line 341, in __init__
            self.threadName = threading.current_thread().name
  1. File /usr/local/lib/python3.11/threading.py, line 1463, in current_thread
        return _DummyThread()
  1. File /usr/local/lib/python3.11/threading.py, line 1433, in __init__
        self._started.set()
  1. File /usr/local/lib/python3.11/threading.py, line 597, in set
        with self._cond:
  1. File /usr/local/lib/python3.11/threading.py, line 275, in __exit__
        return self._lock.__exit__(*args)
  1. File /code/.venv/lib/python3.11/site-packages/ddtrace/profiling/collector/_lock.py, line 259, in __exit__
        self._release(self.__wrapped__.__exit__, *args, **kwargs)
  1. File /code/.venv/lib/python3.11/site-packages/ddtrace/profiling/collector/_lock.py, line 198, in _release
            LOG.debug("Failed to delete _self_acquired_at")

Checklist

  • PR author has checked that all the criteria below are met
  • The PR description includes an overview of the change
  • The PR description articulates the motivation for the change
  • The change includes tests OR the PR description describes a testing strategy
  • The PR description notes risks associated with the change, if any
  • Newly-added code is easy to change
  • The change follows the library release note guidelines
  • The change includes or references documentation updates if necessary
  • Backport labels are set (if applicable)

Reviewer Checklist

  • Reviewer has checked that all the criteria below are met
  • Title is accurate
  • All changes are related to the pull request's stated goal
  • Avoids breaking API changes
  • Testing strategy adequately addresses listed risks
  • Newly-added code is easy to change
  • Release note makes sense to a user of the library
  • If necessary, author has acknowledged and discussed the performance implications of this PR as reported in the benchmarks PR comment
  • Backport labels are set in a manner that is consistent with the release branch maintenance policy

```Python
        try:
            del self._self_acquired_at
        except AttributeError:
            LOG.debug("Failed to delete _self_acquired_at")
```

Above code resulted in an infinite recursion from a customer
environment, by calling `LOG.debug()`. This PR removes `logger` from the
lock profiler as logging any information from lock profiler to customer
environment caused more harm than benefit.

We don't always set the `_self_acquired_at` attribute when `acquire()`
is called. It's set only when the `acquire()` is sampled. And in the
`except` block above, the call to `LOG.debug()` leads to
`acquire()/release()` calls. Then if a subsequent `acquire()` was not
captured, then it will be calling `LOG.debug()` again from `release()`,
leading to an infinite recursion.

1. File `/usr/local/lib/python3.11/logging/__init__.py`, [line
1477](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L1477),
in `debug`
```Python
            self._log(DEBUG, msg, args, **kwargs)
```

2. File `/usr/local/lib/python3.11/logging/__init__.py`, [line
1632](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L1632),
in `_log`
```Python
        record = self.makeRecord(self.name, level, fn, lno, msg, args,
                                 exc_info, func, extra, sinfo)
```

3. File
`/code/.venv/lib/python3.11/site-packages/ddtrace/contrib/internal/logging/patch.py`,
[line
70](https://github.com/DataDog/dd-trace-py/blob/eb81294f4c5ae0ac1b30ece3ef3a81ff00bfae90/ddtrace/contrib/internal/logging/patch.py#L70),
in `_w_makeRecord`
```Python
    record = func(*args, **kwargs)
```

4. File `/usr/local/lib/python3.11/logging/__init__.py`, [line
1601](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L1601),
in `makeRecord`

```Python
        rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
                             sinfo)
```

5. File `/usr/local/lib/python3.11/logging/__init__.py`, [line
341](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L341),
in `__init__`
```Python
            self.threadName = threading.current_thread().name
```

6. File `/usr/local/lib/python3.11/threading.py`, [line
1463](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L1463),
in `current_thread`
```Python
        return _DummyThread()
```

7. File `/usr/local/lib/python3.11/threading.py`, [line
1433](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L1433),
in `__init__`
```Python
        self._started.set()
```

8. File `/usr/local/lib/python3.11/threading.py`, [line
597](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L597),
in `set`
```Python
        with self._cond:
```

9. File `/usr/local/lib/python3.11/threading.py`, [line
275](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L275),
in `__exit__`
```Python
        return self._lock.__exit__(*args)
```

10. File
`/code/.venv/lib/python3.11/site-packages/ddtrace/profiling/collector/_lock.py`,
[line
259](https://github.com/DataDog/dd-trace-py/blob/eb81294f4c5ae0ac1b30ece3ef3a81ff00bfae90/ddtrace/profiling/collector/_lock.py#L259),
in `__exit__`
```Python
        self._release(self.__wrapped__.__exit__, *args, **kwargs)
```

11. File
`/code/.venv/lib/python3.11/site-packages/ddtrace/profiling/collector/_lock.py`,
[line
198](https://github.com/DataDog/dd-trace-py/blob/eb81294f4c5ae0ac1b30ece3ef3a81ff00bfae90/ddtrace/profiling/collector/_lock.py#L198),
in _release
```
            LOG.debug("Failed to delete _self_acquired_at")
```

## Checklist
- [x] PR author has checked that all the criteria below are met
- The PR description includes an overview of the change
- The PR description articulates the motivation for the change
- The change includes tests OR the PR description describes a testing
strategy
- The PR description notes risks associated with the change, if any
- Newly-added code is easy to change
- The change follows the [library release note
guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html)
- The change includes or references documentation updates if necessary
- Backport labels are set (if
[applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting))

## Reviewer Checklist
- [x] Reviewer has checked that all the criteria below are met
- Title is accurate
- All changes are related to the pull request's stated goal
- Avoids breaking
[API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces)
changes
- Testing strategy adequately addresses listed risks
- Newly-added code is easy to change
- Release note makes sense to a user of the library
- If necessary, author has acknowledged and discussed the performance
implications of this PR as reported in the benchmarks PR comment
- Backport labels are set in a manner that is consistent with the
[release branch maintenance
policy](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting)

(cherry picked from commit 29ab7d8)
@github-actions github-actions bot requested review from a team as code owners April 9, 2025 22:05
@github-actions github-actions bot requested review from sanchda and sabrenner April 9, 2025 22:05
@taegyunkim taegyunkim closed this Apr 9, 2025
@taegyunkim taegyunkim reopened this Apr 9, 2025
@taegyunkim taegyunkim enabled auto-merge (squash) April 9, 2025 22:07
Copy link
Contributor Author

github-actions bot commented Apr 9, 2025

CODEOWNERS have been resolved as:

releasenotes/notes/profiling-lock-logging-b334718034fb8f0f.yaml         @DataDog/apm-python
ddtrace/profiling/collector/_lock.py                                    @DataDog/profiling-python

Copy link
Contributor Author

github-actions bot commented Apr 9, 2025

Bootstrap import analysis

Comparison of import times between this PR and base.

Summary

The average import time from this PR is: 232 ± 3 ms.

The average import time from base is: 234 ± 3 ms.

The import time difference between this PR and base is: -2.3 ± 0.1 ms.

Import time breakdown

The following import paths have shrunk:

ddtrace.auto 2.000 ms (0.86%)
ddtrace.bootstrap.sitecustomize 1.340 ms (0.58%)
ddtrace.bootstrap.preload 1.340 ms (0.58%)
ddtrace.internal.products 1.340 ms (0.58%)
ddtrace.internal.remoteconfig.client 0.633 ms (0.27%)
ddtrace 0.660 ms (0.28%)

@pr-commenter
Copy link

pr-commenter bot commented Apr 9, 2025

Benchmarks

Benchmark execution time: 2025-04-15 18:36:53

Comparing candidate commit d9377d9 in PR branch backport-13147-to-3.4 with baseline commit 5ed4bc5 in branch 3.4.

Found 0 performance improvements and 3 performance regressions! Performance is the same for 495 metrics, 2 unstable metrics.

scenario:iast_aspects-ospathbasename_aspect

  • 🟥 execution_time [+427.270ns; +490.537ns] or [+9.325%; +10.706%]

scenario:iast_aspects-ospathdirname_aspect

  • 🟥 execution_time [+388.630ns; +468.513ns] or [+7.571%; +9.127%]

scenario:iast_aspects-ospathsplit_aspect

  • 🟥 execution_time [+456.748ns; +539.270ns] or [+8.566%; +10.114%]

@taegyunkim taegyunkim merged commit e7bd283 into 3.4 Apr 16, 2025
377 checks passed
@taegyunkim taegyunkim deleted the backport-13147-to-3.4 branch April 16, 2025 10:53
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants