classification
Title: gc: stats from multi process are mixed up
Type: Stage: resolved
Components: Interpreter Core Versions: Python 3.9, Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: josh.r, methane, ned.deily
Priority: normal Keywords: patch

Created on 2019-07-31 09:35 by methane, last changed 2019-08-30 21:43 by ned.deily. This issue is now closed.

Files
File name Uploaded Description Edit
t.py methane, 2019-07-31 09:35
Pull Requests
URL Status Linked Edit
PR 15050 merged methane, 2019-07-31 09:35
PR 15076 merged miss-islington, 2019-08-02 07:25
Messages (6)
msg348795 - (view) Author: Inada Naoki (methane) * (Python committer) Date: 2019-07-31 09:35
gc used several PySys_WriteStderr() calls to write stats.
This caused stats mixed up when stderr is shared by multiple
threads or processes.

Attached file (t.py) demonstrates it.
Sometimes stats from two processes are mixed up like this:

```
gc: collecting generation 0...
gc: objects in each generation: 782 0 7759
gc: objects in permanent generation: 0gc: collecting generation 0...

gc: objects in each generation: 782 0 7764
gc: objects in permanent generation: 0gc: done, 781 unreachable, 0 uncollectable, 0.0001s elapsed

gc: done, 781 unreachable, 0 uncollectable, 0.0000s elapsed
```

Writing one stat by one PySys_WriteStderr() reduces this.
msg348796 - (view) Author: Josh Rosenberg (josh.r) * (Python triager) Date: 2019-07-31 10:59
Delaying the write means you don't get an indication of the steps in the process; if someone is trying to debug a crash caused by corruption of the gc list (e.g. due to a bad extension module), deferring the writes means they won't see any output before the crash, where before, they'd see:

gc: collecting generation 0...
gc: objects in each generation:

and numbers for however many gc list traversals succeeded before the corrupt entry in the gc list was hit.
msg348798 - (view) Author: Inada Naoki (methane) * (Python committer) Date: 2019-07-31 11:19
I updated the PR to show "gc: collecting generation 0...\n" before counting objects in each generations.
msg348889 - (view) Author: Inada Naoki (methane) * (Python committer) Date: 2019-08-02 07:25
New changeset bf8162c8c45338470bbe487c8769bba20bde66c2 by Inada Naoki in branch 'master':
bpo-37729: gc: write stats at once (GH-15050)
https://github.com/python/cpython/commit/bf8162c8c45338470bbe487c8769bba20bde66c2
msg349030 - (view) Author: Inada Naoki (methane) * (Python committer) Date: 2019-08-05 07:20
New changeset e8ea34855c7635f8a84b430f17dc01a666f4c0ef by Inada Naoki (Miss Islington (bot)) in branch '3.8':
bpo-37729: gc: write stats at once (GH-15050)
https://github.com/python/cpython/commit/e8ea34855c7635f8a84b430f17dc01a666f4c0ef
msg350893 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-08-30 21:43
See Issue37990 for a report of a regression introduced by these changes.
History
Date User Action Args
2019-08-30 21:43:36ned.deilysetnosy: + ned.deily
messages: + msg350893
2019-08-05 07:21:27methanesetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2019-08-05 07:20:41methanesetmessages: + msg349030
2019-08-02 07:25:52methanesetmessages: + msg348889
2019-08-02 07:25:48miss-islingtonsetpull_requests: + pull_request14823
2019-08-01 07:22:52methanesetversions: - Python 3.7
2019-07-31 11:19:46methanesetmessages: + msg348798
2019-07-31 10:59:44josh.rsetnosy: + josh.r
messages: + msg348796
2019-07-31 09:35:51methanesetkeywords: + patch
stage: patch review
pull_requests: + pull_request14801
2019-07-31 09:35:28methanecreate