regrtest: win_utils decodes typeperf output from the wrong encoding (test suite broken due to cpu usage feature on win 10/ german)

@pfmoore

BPO	36670
Nosy	@pfmoore, @db3l, @vstinner, @tjguk, @zware, @eryksun, @zooba, @ammaraskar, @miss-islington, @LorenzMende, @skoslowski, @heckad
PRs	bpo-36670: fixed encoding issue with libregrtest on win systems #15488 bpo-36670: fixed encoding issue with libregrtest on win systems #16456 bpo-36670: Multiple regrtest bugfixes #16511 [3.8] bpo-36670: Multiple regrtest bugfixes (GH-16511) #16513 [3.7] bpo-36670: Multiple regrtest bugfixes (GH-16511) #16514 bpo-36670, regrtest: Fix TestWorkerProcess.stop() #16530 bpo-36670, regrtest: Fix repr(TestWorkerProcess) #16537 [3.8] bpo-36670: regrtest bug fixes (GH-16537) #16538 bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line #16550 bpo-36670: Enhance regrtest WindowsLoadTracker #16553 [3.8] bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550) #16554 bpo-36670, regrtest: Fix WindowsLoadTracker sampling rate #16555 bpo-36670: regrtest WindowsLoadTracker computes LOAD_FACTOR_1 #16556 [3.8] bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550) #16559 [3.8] bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550) #16560 [3.7] [3.8] bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550) (GH-16560) #16562
Files	win_utils.py: patched win_utils.py with registry lookup for counter name and oemdecoding

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2019-10-03.15:31:37.450>
created_at = <Date 2019-04-19.15:52:37.352>
labels = ['easy', 'type-bug', '3.8', '3.9', '3.7', 'tests', 'OS-windows']
title = 'regrtest: win_utils decodes typeperf output from the wrong encoding (test suite broken due to cpu usage feature on win 10/ german)'
updated_at = <Date 2020-04-14.23:05:24.337>
user = 'https://github.com/LorenzMende'

bugs.python.org fields:

activity = <Date 2020-04-14.23:05:24.337>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-10-03.15:31:37.450>
closer = 'vstinner'
components = ['Tests', 'Windows']
creation = <Date 2019-04-19.15:52:37.352>
creator = 'LorenzMende'
dependencies = []
files = ['48406']
hgrepos = []
issue_num = 36670
keywords = ['patch', 'easy', 'newcomer friendly']
message_count = 35.0
messages = ['340547', '340548', '340550', '340551', '340562', '340575', '340576', '340632', '340797', '340806', '344293', '345076', '348719', '353554', '353555', '353556', '353660', '353664', '353667', '353669', '353670', '353731', '353732', '353768', '353770', '353772', '353779', '353783', '353786', '353832', '353850', '353853', '353857', '353860', '366462']
nosy_count = 12.0
nosy_names = ['paul.moore', 'db3l', 'vstinner', 'tim.golden', 'zach.ware', 'eryksun', 'steve.dower', 'ammar2', 'miss-islington', 'LorenzMende', 'skoslowski', 'heckad']
pr_nums = ['15488', '16456', '16511', '16513', '16514', '16530', '16537', '16538', '16550', '16553', '16554', '16555', '16556', '16559', '16560', '16562']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue36670'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

The test suite fails with the first tests (I assume 1st call of getloadavg of WindowsLoadTracker).
Traceback (most recent call last):
  File "P:\Repos\CPython\cpython\lib\runpy.py", line 192, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "P:\Repos\CPython\cpython\lib\runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "P:\Repos\CPython\cpython\lib\test\__main__.py", line 2, in <module>
    main()
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\main.py", line 653, in main
    Regrtest().main(tests=tests, **kwargs)
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\main.py", line 586, in main
    self._main(tests, kwargs)
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\main.py", line 632, in _main
    self.run_tests()
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\main.py", line 515, in run_tests
    self.run_tests_sequential()
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\main.py", line 396, in run_tests_sequential
    self.display_progress(test_index, text)
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\main.py", line 150, in display_progress
    load_avg_1min = self.getloadavg()
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\win_utils.py", line 81, in getloadavg
    typeperf_output = self.read_output()
  File "P:\Repos\CPython\cpython\lib\test\libregrtest\win_utils.py", line 78, in read_output
    return response.decode()
UnicodeDecodeError: 'utf-8' codec can't decode byte 0x81 in position 67: invalid start byte
##########################################################
The windows 'typeperf "\System\Processor Queue Length" -si 1' command unluckily returns an string with an umlaut which leads to the Decode-Error. This comes up because the <counter> for the typeperf is location dependend. (In german the counter would read \System\Prozessor-Warteschlangenlänge)

I see two possible solutions to this issue.

Raising an exception earlier on creation of WindowsLoadTracker resulting in the same behaviour as if there is no typeperf available (german pythoneers would have a drawback with this)
Getting the typeperf counter correctly from registry (HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Perflib\CurrentLanguage, described here https://social.technet.microsoft.com/Forums/de-DE/25bc6907-cf2c-4dc8-8687-974b799ba754/powershell-ausgabesprache-umstellen?forum=powershell_de)

environment:
Windows 10 x64, 1809, german
cpython @e16467af0bfcc9f399df251495ff2d2ad20a1669
commit of assumed root cause of https://bugs.python.org/issue34060

What does typeperf "\System\Processor Queue Length" -si 1 actually return on your non-English system?

Does it just return an error with the counter's name or is the umalet just in the first header line, i.e this one for me:

"(PDH-CSV 4.0)","\\MSI\System\Processor Queue Length"

If it's the latter then I think the correct fix would be to figure out what encoding typeperf is outputting in and then just decode with that.

Hi Ammar, you are correct.
typeperf returns:
P:\Repos\CPython\cpython>typeperf "\System\Prozessor-Warteschlangenlänge" -si 1

"(PDH-CSV 4.0)","\\ZERO\System\Prozessor-Warteschlangenlänge"
"04/19/2019 19:09:14.510","0.000000"
"04/19/2019 19:09:15.514","0.000000"

So even with correct counter name the outpu needs to be decoded correctly.
I already got a solution to get the location specific counter name from registry - if it helps I'll commit it.

Thank you, could you also share the output if you just give it the English name of the counter?

'crash' mean *nix coredump or Windows equivelent, rather than traceback.

It'll probably be mbcs or oem encoding. Certainly not UTF-8

It'll probably be mbcs or oem encoding. Certainly not UTF-8

Unless the system locale's codepage is set to UTF-8 in Windows 10.

I stepped through this in the debugger. When writing to a pipe, typeperf.exe calls WideCharToMultiByte(CP_OEMCP, ...), so it's "oem".

If the code page is set to UTF-8 then mbcs will still be the right encoding :)

@ammar

Sorry, was off some days. I tried to decode the output with mbcs, solves the issue partly - the counter name is still wrong.
Was able to pick the localization specific counter name from registry and use it for the typeperf.

But the tests fail after several seconds with Broken Pipe Error of the command_stdout pipe.

@ammar - why is the handle closed in start()? If I uncomment it, the load tracker workks fine.

Added the fixed file, may someone evaluate the solution on another windows localization?

Just an FYI that this change is generating warnings on my Windows 10 buildbot with some regularity about a failure to parse testperf output, such as:

Warning -- Failed to parse typeperf output: '"10/01/2019 07:58:50.056"'

from https://buildbot.python.org/all/#/builders/217/builds/487

Now, clearly there's no queue length in that output so the parsing warning is accurate, but does the overall build have to reflect a warning in such cases, given that it's just a test harness issue, and not anything going wrong with the actual tests? Previously any such cases would be ignored silently, so this probably isn't a new issue but just one that is now shows up as an overall build warning.

I don't know why both fields aren't present although it seems plausible that it's just a partial line from the I/O (I don't think it guarantees it receives full lines), and the queue length field would appear on the following read.

Just an FYI that this change is generating warnings on my Windows 10 buildbot with some regularity about a failure to parse testperf output, such as:

Warning -- Failed to parse typeperf output: '"10/01/2019 07:58:50.056"'

Aha, interesting. I added a warning to debug the code.

Now, clearly there's no queue length in that output so the parsing warning is accurate, but does the overall build have to reflect a warning in such cases, given that it's just a test harness issue, and not anything going wrong with the actual tests?

The build is marked as "warning" (orange) which is different than "fail" (red). Warnings are used to detect bugs or interesting issues, but not considered as a regression.

I don't know why both fields aren't present although it seems plausible that it's just a partial line from the I/O (I don't think it guarantees it receives full lines), and the queue length field would appear on the following read.

Right, the code doesn't ensure that a line ends with a newline character. Could you try to run manually the following command to check its output?

typeperf "\System\Processor Queue Length" -si 1

Maybe uncomplete lines should be buffered in read_output().

Oh, I agree it's just a warning, and I suspect few people look into warnings, but since it's not from an actual test, I'm not sure the overall build should be flagged.

The manual typeperf looks fine, but there's no way I could tell visually how the I/O is being done under the covers. My bet is typeperf is probably issuing multiple output calls, one for the leading timestamp and then one for each value. So regrtest just happens to interleave its own read in between the two. The subsequent read would then get the trailing ",####" which the current code would parse normally as it only cares about the second field. In which case it's not even affecting the load monitoring, other than the warning message.

I suspect it's happening on the Windows 10 buildbot as the machine is reasonably fast. But to your earlier comment about things just working previously, I'm not sure there's that much value in adding code to deal with this case.

I'd probably just remove the warning to restore the earlier behavior. The current code still ignores other issues like an actual read failure in read_output. Or, if there's a way to generate the message without it being considered an overall test build warning, that would work too.

I've confirmed the partial read with some local modifications, and the failures are always split between time stamp and value:

Warning -- Failed to parse typeperf output: '"10/02/2019 17:42:26.229"'
0.0
Warning -- Missing first field: ,"0.000000"
0.0

Adding multiple variables to the typeperf command can vary the split position, but I've only seen it at a variable boundary (starting with the comma). So I'm guessing with the current implementation the above is probably the only point where the I/Os can be interleaved.

Also, CRLF seems to only appear at the start of each read, never at the end. You can see that behavior interactively too where the cursor waits at the end of the line between samples. So changes to wait for a complete line to be read would also delay load values by one sample interval.

So I'm thinking just reverting to silently ignoring this case is probably simplest.

Ok, I managed to reproduce the bug using this change:

diff --git a/Lib/test/libregrtest/win_utils.py b/Lib/test/libregrtest/win_utils.py
index f0c17b906f..78429faa89 100644
--- a/Lib/test/libregrtest/win_utils.py
+++ b/Lib/test/libregrtest/win_utils.py
@@ -14,7 +14,7 @@ BUFSIZE = 8192
 LOAD_FACTOR_1 = 0.9200444146293232478931553241
 
 # Seconds per measurement
-SAMPLING_INTERVAL = 5
+SAMPLING_INTERVAL = 0
 # Windows registry subkey of HKEY_LOCAL_MACHINE where the counter names
 # of typeperf are registered
 COUNTER_REGISTRY_KEY = (r"SOFTWARE\Microsoft\Windows NT\CurrentVersion"

I wrote PR 16550 to handle partial lines.

New changeset 3e04cd2 by Victor Stinner in branch 'master':
bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550)
3e04cd2

New changeset c65119d by Victor Stinner in branch 'master':
bpo-36670: Enhance regrtest WindowsLoadTracker (GH-16553)
c65119d

New changeset 098e256 by Victor Stinner in branch 'master':
bpo-36670: Enhance regrtest (GH-16556)
098e256

New changeset de3195c by Victor Stinner in branch '3.8':
[3.8] bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550) (GH-16560)
de3195c

Thanks for the bug report. I was impacted by the bug with my French locale as well.

I pushed a fix based on Lorenz Mende's work, with minor changes. I also enhanced WindowsLoadTracker to handle partial write and report parsing errors as warnings rather than exception.

I pushed other changes to enhance regrtest in general.

The load average is not updated every second and it's value is initialized from the arithmetic mean of the first 5 values of the Processor Queue Length.

New changeset f9016e5 by Miss Islington (bot) in branch '3.7':
[3.8] bpo-36670, regrtest: Fix WindowsLoadTracker() for partial line (GH-16550) (GH-16560)
f9016e5

New changeset b894b66 by Victor Stinner in branch '3.7':
Update libregrtest from master (GH-19517)
b894b66

Navigation Menu

Repository navigation

regrtest: win_utils decodes typeperf output from the wrong encoding (test suite broken due to cpu usage feature on win 10/ german) #80851

22 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

regrtest: win_utils decodes typeperf output from the wrong encoding (test suite broken due to cpu usage feature on win 10/ german) #80851

Description

Activity

LorenzMende commented on Apr 19, 2019

ammaraskar commented on Apr 19, 2019

LorenzMende commented on Apr 19, 2019

ammaraskar commented on Apr 19, 2019

terryjreedy commented on Apr 20, 2019

zooba commented on Apr 20, 2019

eryksun commented on Apr 20, 2019

zooba commented on Apr 22, 2019

LorenzMende commented on Apr 24, 2019

22 remaining items

db3l commented on Oct 2, 2019

vstinner commented on Oct 2, 2019

db3l commented on Oct 2, 2019

db3l commented on Oct 2, 2019

vstinner commented on Oct 2, 2019

vstinner commented on Oct 2, 2019

vstinner commented on Oct 3, 2019

vstinner commented on Oct 3, 2019

vstinner commented on Oct 3, 2019

vstinner commented on Oct 3, 2019

miss-islington commented on Oct 3, 2019

vstinner commented on Apr 14, 2020

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions