Log file for stress tests (on Windows)?

[sp00n]

Is there any way to create a log file during stress testing?
In the Command Lines.txt there's an entry for -o {output path}, however this doesn't seem to work for stress testing, i.e. no output file is generated.

(And if I put the -o parameter before loading the config file like so: 00-x86.exe -o C:\Temp config stressTest.cfg it tells me it's an invalid parameter, but that's just a side note.)

I also tried to use output redirection via > logfile.txt 2>&1, but at least on Windows this produces only an empty log file, despite the binary being a console application. Resp. it does include the ^C from when I cancel the execution with CTRL+C.

So, is there any way to create a log file for a stress test on Windows?

[Mysticial]

Unfortunately no, the program doesn't log the stress tests. I never thought it was necessary because the only interesting output would be when it fails. And when it fails, it stops.

As for why redirection isn't working. I honestly have no idea. It's not something that I use for this program.

y-cruncher has uh... never been great for logging. :(

[sp00n]

Ok, thanks for the answer.
It's really curious why the output redirection doesn't work, maybe it has something to do how the binaries put out the colored text, but I really have no idea.

By the way, I also posted this question in the mersenneforum.org sub forum, but hadn't received an answer there (so i now linked to this issue)

[sp00n]

y-cruncher has uh... never been great for logging. :(

Hmm, what are you using to output the text in the binaries? Maybe I can find some more information of why this is isn't working and a possible workaround.

In the meantime I've also tried to catch the output in PowerShell with:

• $output = .\y-cruncher.exe config stressTest.cfg
• .\y-cruncher.exe config stressTest.cfg *> test.log
• .\y-cruncher.exe config stressTest.cfg | Tee-Object -FilePath .\test.log
• Start-Process -FilePath "${dir}y-cruncher.exe" -ArgumentList "config stressTest.cfg" -RedirectStandardOutput "${dir}test_output.log" -RedirectStandardError "${dir}test_error.log"

But none of this worked either.
The only thing it does catch is the Press any key to continue . . . message when some error in the syntax had occurred (e.g. when I mistyped the name of the config file).

[Mysticial]

WriteConsoleW

https://github.com/Mysticial/y-cruncher/blob/master/trunk/Source/PublicLibs/ConsoleIO/ConsoleIO_Windows.ipp#L60

[sp00n]

From the Microsoft doc:

WriteConsole fails if it is used with a standard handle that is redirected to a file. If an application processes multilingual output that can be redirected, determine whether the output handle is a console handle (one method is to call the GetConsoleMode function and check whether it succeeds). If the handle is a console handle, call WriteConsole. If the handle is not a console handle, the output is redirected and you should call WriteFile to perform the I/O. Be sure to prefix a Unicode plain text file with a byte order mark. For more information, see Using Byte Order Marks.

This article seems to be relevant for this issue as well:
http://archives.miloush.net/michkap/archive/2010/10/07/10072032.html

And apparently this even caused some problems for the WSL integration in Windows:
microsoft/terminal#89

IMO it's a bit stupid that this needs to be handled by the developer and doesn't "just work" out of the box, but oh well.

[Micke3rd]

because the only interesting output would be when it fails. And when it fails, it stops.

Hi @Mysticial ,
unfortunately not always. If you throw a KeyNotFoundException you don't let it out, but catch it. Followed by a "Pause", what keeps the cruncher running, although it does nothing anymore.
I assume unhandled exceptions are triggering the same behavior.

Regarding additional effort for logging - if you don't catch critical exceptions, or you re-throw them, that should already deliver the needed informations to the environment.
Would like to add my vote to @sp00n's request

[Mysticial]

Lemme check the behavior. It's supposed to stop after the current iteration if any thread has errored.

[Micke3rd]

to reproduce

• create filled xyz.cfg
• inside delete a row of a key e.g. "LogicalCores : [4]"
• call: y-cruncher config xyz.cfg

result:
"Exception Encountered: KeyNotFoundException
LogicalCores
press key to continue ..... "

My cpu fits to "20-ZN3 ~ Yuzuki.exe"

[Mysticial]

Oh I meant what the stress tester does when a thread errors. The behavior you're seeing with normal errors is expected.

[Micke3rd]

Also with stress test errors, y-cruncher always ends with "press key to continue".
This means - regardless of whether the test fails, succeeds, or encounters other exceptions, the process ends up in a wait state. So from a machine reading perspective, the status or result is unclear.
Additionally these stress tests often made on machines with unstable behavior - like app crashes or sudden reboots. But with a closed y-cruncher window the only report is lost.
Hence the request for any kind of log-able feedback.

[Mysticial]

Also with stress test errors, y-cruncher always ends with "press key to continue".
This means - regardless of whether the test fails, succeeds, or encounters other exceptions, the process ends up in a wait state. So from a machine reading perspective, the status or result is unclear.

If you pass pause:-2 as one of the first parameters, it will skip the pause. At least for computations. I never tested if it works on stress tester.

Startup Parameters:

These parameters are all optional and must be passed before the [option] parameter.


Pause at End of Computation:

    pause:1   	Always pause at the end of a computation.
    pause:0     Default behavior - automatically decide whether to pause.
    pause:-1    Never pause at the end of a computation. Will pause on errors.
    pause:-2    Never pause at all, not even on errors.

    By default, y-cruncher will try to detect if it's run manually, or from the
    command line. If run manually, it will pause at the end of the computation to
    prevent the window from automatically closing. Otherwise, it will not pause.

[Micke3rd]

thank you. But with pause:-2 it would be worse than without. Neither a result in the GUI nor as a file.
The "pause:-1" logic presumably fits for the computation, but for error checking it is inconsistent. Successful runs and crashs are showing identical results.
But ok, lets stop at this point.

[sp00n]

From the Microsoft doc:

WriteConsole fails if it is used with a standard handle that is redirected to a file. If an application processes multilingual output that can be redirected, determine whether the output handle is a console handle (one method is to call the GetConsoleMode function and check whether it succeeds). If the handle is a console handle, call WriteConsole. If the handle is not a console handle, the output is redirected and you should call WriteFile to perform the I/O. Be sure to prefix a Unicode plain text file with a byte order mark. For more information, see Using Byte Order Marks.

Would it maybe be possible to replace the WriteConsoleW call with something like this?

// Either write directly to the console or allow redirection / piping of the output
DWORD ignored;
bool32 isConsole = GetConsoleMode(handle, &ignored);

if (isConsole) {
	WriteConsoleW(handle, data, block, &written, nullptr);
}
else {
	WriteFile(handle, data, block - 1, &written, nullptr);
}

[Mysticial]

Conceptually I think it will work. Just not exactly as you have written because of the length and encoding discrepancies.

[sp00n]

Yeah, it probably should be something like block * sizeof(WCHAR).
Do you have any plans to implement this?

I'm currently looking into redirecting the WriteConsoleW calls to WriteFile using DLL injection with Detours, but without luck so far.

[Mysticial]

I think I have something working locally. But it's probably gonna be some months before it gets out since the project is in the middle of something.

[sp00n]

I have managed to redirect the calls to WriteConsole to WriteFile using Detours now, however it suffers from a flaw in Detours itself (resp. an underlying mechanic), where Detours can only work in directories that contain ASCII characters.
A limited amount of UTF-8 characters would also work - not including Asian or Arab characters - if the executable where the DLL is going to be injected supports the relatively new activeCodePage manifest setting.

Unfortunately adding this manifest setting to only the "wrapper" exe that will inject the DLL to reroute the WriteConsole calls does not suffice, the original executable itself has to have this setting enabled as well. And the y-cruncher binaries unfortunately don't have it set.
I even tried to add a manifest to the already existing binary files, but then the exe would just quit with an error message (maybe there's some CRC check?).

Maybe that's something you could consider adding for the next revision as well, as the reason why you chose WriteConsole seems to have been Unicode support in the first place?

[Mysticial]

Detours seems specific to the DLL injection. So is this work-around only needed if you're DLL-injecting? The next version will have the WriteFile redirection thing you suggested.

Yes, WriteConsole (specifically WriteConsoleW) was to support Unicode.

[sp00n]

Yes, Detours is for hooking into system calls and "detouring" them.
The activeCodePage manifest setting however basically should remove the need to specifically call the "wide" unichar W variants of functions.

Until recently, Windows has emphasized "Unicode" -W variants over -A APIs. However, recent releases have used the ANSI code page and -A APIs as a means to introduce UTF-8 support to apps. If the ANSI code page is configured for UTF-8, -A APIs typically operate in UTF-8. This model has the benefit of supporting existing code built with -A APIs without any code changes.

It does require Windows 10 1903 at least though.

[Mysticial]

Here's the current implementation that's slated for v0.8.1 barring any further changes. It picks between WriteConsoleW and WriteFile depending on whether it's a console.

Probably worth checking to see if WriteFile writing UTF-8 is okay since that's the current behavior. Can be switched to UTF-16 if needed.

void internal_print_console(const std::wstring& str){
    const DWORD MAX_BLOCK = 4096;

    HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);

    upL_t length = str.size();
    const wchar_t* data = str.c_str();

    //  Split it up into blocks of no more than MAX_BLOCK characters.
    while (length > 0){
        DWORD block = length < MAX_BLOCK ? (DWORD)length : MAX_BLOCK;
        DWORD written;
        WriteConsoleW(handle, data, block, &written, nullptr);
        data += block;
        length -= block;
    }
}
void internal_write_file(const std::string& str){
    const DWORD MAX_BLOCK = 4096;

    HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);

    upL_t length = str.size();
    const char* data = str.c_str();

    //  Split it up into blocks of no more than MAX_BLOCK characters.
    while (length > 0){
        DWORD block = length < MAX_BLOCK ? (DWORD)length : MAX_BLOCK;
        DWORD written;
        WriteFile(handle, data, block, &written, nullptr);
        data += block;
        length -= block;
    }
}
YM_NO_INLINE upL_t print(const std::string& str, char color){
    std::u32string u32 = StringTools::utf8_to_utf32(str);

    ConsoleLockScope lock;

    HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);
    DWORD ignored;
    bool is_console = GetConsoleMode(handle, &ignored);

    set_color(color);
    if (is_console){
        internal_print_console(StringTools::utf32_to_wstr(u32));
    }else{
        internal_write_file(str);
    }
    sequence++;
    return u32.size();
}
YM_NO_INLINE upL_t print(const std::wstring& str, char color){
    std::u32string u32 = StringTools::wstr_to_utf32(str);

    ConsoleLockScope lock;

    HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);
    DWORD ignored;
    bool is_console = GetConsoleMode(handle, &ignored);

    set_color(color);
    if (is_console){
        internal_print_console(str);
    }else{
        internal_write_file(StringTools::utf32_to_utf8(u32));
    }
    sequence++;
    return u32.size();
}

[Mysticial]

The above changes went into v0.8.1. Worth checking to see if this is done?

[sp00n]

Huuu, long time.
So I've finally tested this, it now works with "19-ZN2 ~ Kagari.exe" config stressTest.cfg > logfile-console-redirect.txt 2>&1.
However this produces no visible output (as expected), so I tested it also with this command:

powershell ".\19-ZN2` ~` Kagari.exe config stressTest.cfg 2>&1 | Tee logfile-powershell-tee.txt"

(Needed to backtick escape the spaces in the filename for PowerShell)

This also works, and also displays the output at the same time. You can even control the main y-cruncher.exe with this command and it will pipe everything to the log file.
Either way is missing the colors in the console of course, but that's also expected.

I noticed one minor issue, it's introducing additional empty lines when running the tests this way, both in the output and in the logfile (with both commands):

Allocating Memory...
  Core   2:  21.3 MiB  node 0 (100%)
  Core   3:  21.3 MiB  node 0 (100%)

Iteration: 0  Total Elapsed Time: 0.013 seconds  ( 0.000 minutes )


Running BKT:

Running BKT: Passed  Test Speed:  1.01 * 10^09  bits / sec


Running BBP:

Running BBP: Passed  Test Speed:  1.56 * 10^08  terms / sec


Running SFT:

Running SFT: Passed  Test Speed:  3.11 * 10^09  bits / sec

Besides that, it seems to work fine! Although I haven't tested it with UTF8/UTF16 directory names.

I will probably still stay with my Detour DLL I mentioned before, as this way I can have both the color output for the y-cruncher window and the log file, and I haven't heard back any problems with it so far.

I assume to support both the color output and a log file out of the box you would need to write a dedicated log file function, instead of only changing the output from WriteConsoleW to WriteFile.

[Mysticial]

Looks like the problem is coming from the way y-cruncher overwrites lines. It does it by printing \r followed by 79 spaces.

Properly fixing this will be trickier. It's too not difficult to fix the current stuff by simply buffering the lines until a newline is printed (and throwing away everything from the last \r). But there's a different kind of status print that's multi-line which is currently not used, but may happen in the future. This one will be nasty to deal with.

As for the colors, I don't think that can be easily fixed. Though it might actually work on Linux since it uses escape codes and are thus part of the stream that's being printed.

[sp00n]

To be fair, the empty lines aren't really a problem, just a cosmetic issue. Anyone parsing the output should easily be able to work with the current output.
Regarding the colors, as mentioned I think the only way to keep the colors and generate a logfile would be a dedicated function that takes the output and writes it to the log.
By the way, this is the way I've done it with Detours. Probably not the best way (I'm seriously lacking knowledge of C/C++/C#), but it works:
https://github.com/sp00n/WriteConsoleToWriteFileWrapperDll/blob/master/WriteConsoleToWriteFileWrapper/dllmain.cpp#L27

[Mysticial]

I assume you're stripping color codes because this is being used for other applications too right? y-cruncher on Windows doesn't use color codes.

[sp00n]

No, I made this purely for y-cruncher. It's been a while, but I think I remember that when I directly forwarded the output to the logfile it was unreadable.

// Edit
It may also have been a relic from when I tried to make it readable though, I really can't remember.

[Mysticial]

Then maybe Windows itself is adding it?

[sp00n]

Maybe Windows or Detours does it when trying to read the output. 🤷

[Mysticial]

Will change the write file function to this:

void internal_write_file(const std::string& str){
    const DWORD MAX_BLOCK = 4096;

    HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE);

    std::string actual_print;

    //  Process the string to remove any overwritten status lines.
    static std::string buffer;
    for (size_t c = 0; c < str.size(); c++){
        char ch = str[c];
        switch (ch){
        case '\r':
            if (str[c + 1] != '\n'){
                buffer.clear();
            }
            break;

        case '\n':
            buffer += ch;
            actual_print += buffer;
            buffer.clear();
            break;

        default:
            buffer += ch;
        }
    }

    upL_t length = actual_print.size();
    const char* data = actual_print.c_str();

    //  Split it up into blocks of no more than MAX_BLOCK characters.
    while (length > 0){
        DWORD block = length < MAX_BLOCK ? (DWORD)length : MAX_BLOCK;
        DWORD written;
        WriteFile(handle, data, block, &written, nullptr);
        data += block;
        length -= block;
    }
}

This should fix the new lines in the piped file. But it won't fix the colors through Tee.

[Mysticial]

I just noticed that the latest console on Windows 10 supports the POSIX color codes. That doesn't mean I can switch to it since I do maintain backwards compatibility with Windows 7 for now.

[Mysticial]

Apparently the change to make piped log files look nice broke the status lines in BenchMate.

BenchMate is piping stdout into custom handler. y-cruncher detects it as pipe instead of a console and thus suppresses the refreshing status lines that mess up log files. BenchMate has some special handling to copy the behavior of the console so that the updating status lines show up correctly within BenchMate's output window. This also explains why BenchMate loses the colors since it only captures the text that is piped whereas the colors are doing using WinAPI calls.

Had a discussion about this with the BenchMate developer and I'll be adding new command line options to control both the behavior of the status lines as well as the way colors are done.

For now the plan for v0.8.6 is that BenchMate will pass:
y-cruncher colors:ansi status-line:CR

This will allow BenchMate to get both the refreshing status-lines as well as the console colors.

In your case, you can omit both options to preserve the behavior of v0.8.5. Though I'm not sure exactly what you're doing with the piping to log file.

[sp00n]

I'm just periodically pulling the content from the y-cruncher output window, save it to a log file and simultaneously check for errors. I don't redirect the whole output into a new window, which I think BenchMate does, the original y-cruncher window is still there.
So I think I'm not going to be affected, although maybe since I try to strip the colors to begin with, there might be a change.

Do you have any ETA yet for 0.8.6?

[Mysticial]

Do you have any ETA yet for 0.8.6?

Nope. Barring a difficult-to-fix bug or some new interesting hardware, I don't plan on releasing anything until next year.

[Mysticial]

I'm just periodically pulling the content from the y-cruncher output window, save it to a log file and simultaneously check for errors. I don't redirect the whole output into a new window, which I think BenchMate does, the original y-cruncher window is still there. So I think I'm not going to be affected, although maybe since I try to strip the colors to begin with, there might be a change.

Do you have any ETA yet for 0.8.6?

How are you pulling the content of the console window? Is there an API for that? Or are you intercepting the WinAPI calls to WriteConsole() or WriteFile() to snoop them?

BenchMate does DLL injection to intercept these. Since v0.8.6 is so far away, I pushed a minor patch just for BenchMate to let it trick y-cruncher into thinking it's printing to a console so it keeps doing the status prints. The proper fix will come in v0.8.6 with the extra flags to explicitly control that behavior.

[sp00n]

I'm using the Microsoft Detours package to inject a DLL that hooks into WriteConsoleW and redirects the output (after some parsing) to a WriteFile call.

https://github.com/sp00n/WriteConsoleToWriteFileWrapperDll/blob/master/WriteConsoleToWriteFileWrapper/dllmain.cpp#L27