Windows Powershell logging prevents Corecycler script from running correctly

[zxcvxzcv-johndoe]

Hello,

I guess its possible this issue is somehow related to my comment #72 (comment)

I am having an issue with the latest CoreCycler-v0.10.0.0alpha5 and v0.9.6.2 where corecycler doesn't actually cycle cores properly.

I tested older version CoreCycler-v0.8.0.0 and it works perfectly.

Last night I ran CoreCycler-v0.10.0.0alpha5 7,5 hours with the BreadPit's settings and it only managed to test from Core 0 (CPU 0 and 1) -> Finished testing Core 3 (CPU 6 and 7) on my 5700X3D so it tested 50%.

And the problem is that testing those cores seem to take exponentially more time during the night, from Windows Event logs:

14.12.2024 00:55 Started testing Core 0 (CPU 0 and 1)
14.12.2024 01:18 Finished testing Core 0 (CPU 0 and 1) - Test completed in 00h 23m 00s
14.12.2024 01:18 Started testing Core 1 (CPU 2 and 3)
14.12.2024 01:14 Finished testing Core 1 (CPU 2 and 3) - Test completed in 00h 22m 32s
14.12.2024 01:41 Started testing Core 2 (CPU 4 and 5)
14.12.2024 02:35 Finished testing Core 2 (CPU 4 and 5) - Test completed in 00h 54m 37s
14.12.2024 02:35 Started testing Core 3 (CPU 6 and 7)
14.12.2024 06:24 Finished testing Core 3 (CPU 6 and 7) - Test completed in 03h 48m 17s
14.12.2024 06:24 Started testing Core 4 (CPU 8 and 9)
14.12.2024 08:26 I woke up and pressed Ctrl-C

	CoreCycler was terminated

The log files for this run are stored in:
C:\Temp\CoreCycler-v0.10.0.0alpha5\logs\CoreCycler_2024-12-14_00-55-41_YCRUNCHER_19-ZN2 ~ KAGARI.log
C:\Temp\CoreCycler-v0.10.0.0alpha5\logs\y-cruncher: yCruncher_2024-12-14_00-55-41_mode_19-ZN2 ~ KAGARI.log

Summary:
Run time: 07 hours, 30 minutes, 46 seconds
Iterations: 1 started / 0 completed
Tested cores: 5 cores / 5 tests
Core 0 (1x), Core 1 (1x), Core 2 (1x), Core 3 (1x), Core 4 (1x)
No core has thrown an error
No WHEA errors were observed during the test

Logs are here
yCruncher_2024-12-14_00-55-41_mode_19-ZN2 ~ KAGARI.log
CoreCycler_2024-12-14_00-55-41_YCRUNCHER_19-ZN2 ~ KAGARI.log

Just to make sure that I understand how to configure this, I tested the older version (which I remember worked few years back) CoreCycler-v0.8.0.0 and with that when I configure "runtimePerCore = 20" it cycles the cores every 20 seconds and I can see that in the Task Manager.

(Of course that 20 seconds is just that its easier to see it works, not for proper testing)

I also tested that for me CoreCycler-v0.10.0.0alpha5 with the default config and "stressTestProgram = YCRUNCHER" and "runtimePerCore = 20" or "runtimePerCore = 20s" doesn't actually cycle the cores in 20 seconds, or probably never.

So with "runtimePerCore = 20" all CoreCycler-v0.10.0.0alpha5 , CoreCycler-v0.8.0.0 and v0.9.6.2 versions list "Runtime per core" as 20 seconds in the CMD window, but only CoreCycler-v0.8.0.0 actually cycles the cores every 20 seconds.

[sp00n]

Okay, to be honest, I have no idea what's going on there. The timestamp in the logs are all over the place, it takes minutes what should take milliseconds, and the time jumps back and forth:

              +++ 00:55:58 - Getting new log file entries
              +++            Getting new log entries starting at position 0 / Line 0
              +++            The new log file entries:
              +++            - [Line 1] 
              +++            - [Line 2] 
              +++            - [Line 3] 2024-12-14 00:55:45
              +++            - [Line 4] 
              +++            - [Line 5] Checking processor/OS features...
              [...]
              +++            - [Line 49] 
              +++            - [Line 50] Allocating Memory...
              +++            - [Line 51]   Core   2:  20.5 MiB  node 0 (100%)
              +++            - [Line 52]   Core   3:  20.5 MiB  node 0 (100%)
              +++            - [Line 53] 
              +++            - [Line 54] Iteration: 0  Total Elapsed Time: 0.015 seconds  ( 0.000 minutes )
              +++            - [Line 55] 
              +++            - [Line 56]                                                                                
              +++            - [Line 57] Running N63: 
              +++            New file position: 1855 / Line 57
              +++ 00:58:29 - Automatic runtime per core selected
              +++            No passed tests found yet, assuming we're at the very beginning of the run
              +++ 01:03:43 - Checking for stress test errors
              +++            Checking the new y-cruncher log entries...
              +++ 01:06:19 - Looking for new WHEA errors
              +++            Core Start Date:        14/12/2024 00:55:46
              +++            Stored WHEA Error Date: -1
              +++            Last WHEA Error Date:   -1
              +              No new WHEA error
              +   01:03:43 - Checking CPU usage: 219ms (expected: 200ms, lower limit: 100ms)
              +++ 
              +++ 01:06:19 - Tick 2 of max 8640
              +++            Remaining max runtime: 85767s
              +++ 01:06:28 - Suspending the stress test process for 1000 milliseconds
              +   Suspending threads for process: 5016 - 19-ZN2 ~ Kagari
              +++            ID: - 16780 ok - 10108 ok - 16792 ok - 14844 ok
              +++            Suspended: 4
              +++ 01:06:29 - Resuming the stress test process

              +   01:09:38 - The last passed test: N63
              +              The number of tests to run:      1
              +              The number of tests already run: 1
              +   
              +              The number of unique test names matches the number of the selected test names!
           Test completed in 00h 23m 00s
           All tests have been run for this core, proceeding to the next one
              +++ Adding Event Log entry: core_finished
              +++ Adding the Windows Event Log entry:
              +++ [EVENTLOG] Finished testing Core 0 (CPU 0 and 1)
              +++ [EVENTLOG] 
              +++ [EVENTLOG] Test completed in 00h 23m 00s
              +++ Trying to switch to a new core (2 of 8) [index 1 of 7]
              +   Still available cores:
              +   1, 2, 3, 4, 5, 6, 7
              +   The selected core to test: 1
01:18:47 - Set to Core 1 (CPU 2 and 3)

Nothing in there looks like it should. It's as if the script was frozen and only woke up sporadically.

As you mentioned that y-cruncher itself was also behaving weird in the other comment, maybe setting stressTestProgramPriority = High in the [Debug] section could work for you.
It is now set to Normal by default, but in earlier version it was set to High. Even though setting it to a higher priority could cause such dropouts, maybe for you it's the opposite. 😵
Or maybe even Normal is too much, in which case you could also try BelowNormal or even Idle instead.

[zxcvxzcv-johndoe]

Okay, I managed to figure out half of the problems :)

Basically newer versions of corecycler don't work properly when Powershell logging is enabled in Windows.

Something corecycler does causes Powershell logging to write logs at full speed which causes those funny issues how it looks like the script was frozen and woken up etc.

Here's how you can replicate the issue:

This last one almost certainly is not required, those file-based logs don't really get filled up

And you need to restart your computer when you enable or disable the Powershell logging using gpedit.msc

So entries similar as below fill out the Event Log -> Applications and Services Logs -> Windows PowerShell and Event Log -> Applications and Services Logs -> Microsoft -> Windows -> PowerShell -> Operational when you run the newer versions of corecycler, and it doesn't happen with old versions (or other programs, Powershell logging isn't/shouldn't be something super special or rare)

Pipeline execution details for command line: Update-TypeData -TypeName System.Collections.HashTable -MemberType ScriptMethod -MemberName ToString -Value { return ($this | Format-List | Out-String) } -Force
. 

Context Information: 
	DetailSequence=1
	DetailTotal=1

	SequenceNumber=28166

	UserId=DESKTOP-XXXX\admin.XXXX
	HostName=Windows PowerShell ISE Host
	HostVersion=5.1.26100.2161
	HostId=639ade22-7518-4d94-8a10-5a7188a56276
	HostApplication=C:\WINDOWS\system32\WindowsPowerShell\v1.0\PowerShell_ISE.exe
	EngineVersion=5.1.26100.2161
	RunspaceId=67aa3c4b-f2e5-4074-8b2b-a4ebbe32c09c
	PipelineId=11
	ScriptName=C:\Temp\CoreCycler-v0.10.0.0alpha5\script-corecycler.ps1
	CommandLine=Update-TypeData -TypeName System.Collections.HashTable -MemberType ScriptMethod -MemberName ToString -Value { return ($this | Format-List | Out-String) } -Force
 

Details: 
CommandInvocation(Format-List): "Format-List"
CommandInvocation(Out-String): "Out-String"
ParameterBinding(Format-List): name="InputObject"; value="

Name  : Line
Value : 

Name  : LineNumber
Value : 10



"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatStartData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.GroupStartData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatEntryData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatEntryData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.GroupEndData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatEndData"

And

CommandInvocation(Format-List): "Format-List"
CommandInvocation(Out-String): "Out-String"
ParameterBinding(Format-List): name="InputObject"; value="

Name  : Line
Value :     Node  0:  0-15 

Name  : LineNumber
Value : 16



"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatStartData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.GroupStartData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatEntryData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatEntryData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.GroupEndData"
ParameterBinding(Out-String): name="InputObject"; value="Microsoft.PowerShell.Commands.Internal.Format.FormatEndData"


Context:
        Severity = Informational
        Host Name = ConsoleHost
        Host Version = 5.1.26100.2161
        Host ID = d365cc95-5e91-429b-8f0f-e25438bbe0ed
        Host Application = powershell.exe -ExecutionPolicy Bypass -File C:\Temp\CoreCycler-v0.10.0.0alpha5\script-corecycler.ps1
        Engine Version = 5.1.26100.2161
        Runspace ID = ac493e1f-74c2-40e9-a688-27d5ca2a0e12
        Pipeline ID = 1
        Command Name = Format-List
        Command Type = Cmdlet
        Script Name = C:\Temp\CoreCycler-v0.10.0.0alpha5\script-corecycler.ps1
        Command Path = 
        Sequence Number = 45230
        User = DESKTOP-XXXX\admin.XXXX
        Connected User = 
        Shell ID = Microsoft.PowerShell


User Data:

I poked through the Powershell code quickly but I couldn't figure out how to fix that.

And the other issue regarding "FATAL ERROR: Could not determine the stress test program process ID! (looking for XXXX)" still persists and its not related to that Powershell logging. I will update that other thread on it.

edit: I also managed to fix the other issue regardind Process ID, I updated that other thread again.

[sp00n]

I've never heard of Powershell logging before, and no one else reported this issue, so I'm pretty sure it is kind of rare. ;)

I'll have to look up what it does exactly, and if something in the code is triggering that.
I am overriding Write-Verbose and Write-Debug with my own custom functions (because I didn't know these existed when I created the project), which could maybe trigger it. That's something you could actually test, just search and replace all occurrences with another name (e.g. Write-VerboseText and Write-DebugText).
I haven't had yet the chance to test this logging setting for myself.

[sp00n]

Just as an update, I now tried simply adding a Start-Transcript to the start of the script, and the script execution stops. to. a. crawl.

So for the time being I cannot recommend enabling it, even after renaming WriteVerbose and WriteDebug.