Improve logging

[jp7677]

Took a look at our logging, with this PR it looks like:

ACC startup and benchmark run.

dxvk-nvapi-log

```syslog ---------- 2024-05-31 16:53:01 ---------- dxvk-nvapi:0308:0312:NvAPI_QueryInterface (0xad298d3f): Unknown function ID dxvk-nvapi:0308:0312:NvAPI_Initialize: Enter dxvk-nvapi:0308:0312:DXVK-NVAPI v0.7.0-23-g107f990 (AC2-Win64-Shipping.exe) dxvk-nvapi:0308:0312:Successfully acquired Vulkan vkGetInstanceProcAddr @ 0x6ffffbc1d310 dxvk-nvapi:0308:0312:Successfully loaded nvml.dll dxvk-nvapi:0308:0312:NVML loaded and initialized successfully dxvk-nvapi:0308:0312:NvAPI Device: NVIDIA GeForce RTX 3090 (555.42.2) dxvk-nvapi:0308:0312:NvAPI Output: \\.\DISPLAY1 dxvk-nvapi:0308:0312:<-NvAPI_Initialize: OK dxvk-nvapi:0308:0312:NvAPI_QueryInterface (0x33c7358c): Unknown function ID dxvk-nvapi:0308:0312:NvAPI_QueryInterface (0x593e8644): Unknown function ID dxvk-nvapi:0308:0312:NvAPI_D3D11_IsNvShaderExtnOpCodeSupported: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_IsNvShaderExtnOpCodeSupported (20/NV_EXTN_OP_UINT64_ATOMIC): OK dxvk-nvapi:0308:0312:NvAPI_D3D11_IsNvShaderExtnOpCodeSupported: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_IsNvShaderExtnOpCodeSupported (1/NV_EXTN_OP_SHFL): OK dxvk-nvapi:0308:0312:NvAPI_D3D_GetCurrentSLIState: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D_GetCurrentSLIState: OK dxvk-nvapi:0308:0312:NvAPI_DISP_GetDisplayIdByDisplayName: Enter dxvk-nvapi:0308:0312:<-NvAPI_DISP_GetDisplayIdByDisplayName (\\.\DISPLAY1): OK dxvk-nvapi:0308:0312:NvAPI_Disp_GetHdrCapabilities: Enter dxvk-nvapi:0308:0312:<-NvAPI_Disp_GetHdrCapabilities (0x10001): OK dxvk-nvapi:0308:0312:NvAPI_EnumPhysicalGPUs: Enter dxvk-nvapi:0308:0312:<-NvAPI_EnumPhysicalGPUs: OK dxvk-nvapi:0308:0312:NvAPI_GPU_GetPstates20: Enter dxvk-nvapi:0308:0312:<-NvAPI_GPU_GetPstates20: No implementation dxvk-nvapi:0308:0312:NvAPI_D3D11_BeginUAVOverlap: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_BeginUAVOverlap: OK dxvk-nvapi:0308:0312:NvAPI_QueryInterface NvAPI_D3D11_SetNvShaderExtnSlot: Not implemented method dxvk-nvapi:0308:0692:NvAPI_D3D_GetObjectHandleForResource: Enter dxvk-nvapi:0308:0692:<-NvAPI_D3D_GetObjectHandleForResource: OK dxvk-nvapi:0308:0692:NvAPI_D3D_SetResourceHint: Enter dxvk-nvapi:0308:0692:<-NvAPI_D3D_SetResourceHint: No implementation dxvk-nvapi:0308:0312:NvAPI_Initialize: Enter dxvk-nvapi:0308:0312:<-NvAPI_Initialize: OK dxvk-nvapi:0308:0312:NvAPI_DRS_CreateSession: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_CreateSession: OK dxvk-nvapi:0308:0312:NvAPI_DRS_LoadSettings: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_LoadSettings: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetBaseProfile: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetBaseProfile: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10afb76b/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_EnumPhysicalGPUs: Enter dxvk-nvapi:0308:0312:<-NvAPI_EnumPhysicalGPUs: OK dxvk-nvapi:0308:0312:NvAPI_GetLogicalGPUFromPhysicalGPU: Enter dxvk-nvapi:0308:0312:<-NvAPI_GetLogicalGPUFromPhysicalGPU: OK dxvk-nvapi:0308:0312:NvAPI_GPU_GetLogicalGpuInfo: Enter dxvk-nvapi:0308:0312:<-NvAPI_GPU_GetLogicalGpuInfo: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10e41df2/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_QueryInterface (0xf2400ab): Unknown function ID dxvk-nvapi:0308:0312:NvAPI_EnumPhysicalGPUs: Enter dxvk-nvapi:0308:0312:<-NvAPI_EnumPhysicalGPUs: OK dxvk-nvapi:0308:0312:NvAPI_GetLogicalGPUFromPhysicalGPU: Enter dxvk-nvapi:0308:0312:<-NvAPI_GetLogicalGPUFromPhysicalGPU: OK dxvk-nvapi:0308:0312:NvAPI_GPU_GetLogicalGpuInfo: Enter dxvk-nvapi:0308:0312:<-NvAPI_GPU_GetLogicalGpuInfo: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10e41df2/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_GPU_GetArchInfo: Enter dxvk-nvapi:0308:0312:<-NvAPI_GPU_GetArchInfo: OK dxvk-nvapi:0308:0312:NvAPI_SYS_GetDriverAndBranchVersion: Enter dxvk-nvapi:0308:0312:<-NvAPI_SYS_GetDriverAndBranchVersion: OK dxvk-nvapi:0308:0312:NvAPI_DRS_CreateSession: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_CreateSession: OK dxvk-nvapi:0308:0312:NvAPI_QueryInterface (0xa782ea46): Unknown function ID dxvk-nvapi:0308:0312:NvAPI_DRS_FindApplicationByName: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_FindApplicationByName (Z:\home\jpeters\.local\share\Steam\steamapps\common\Assetto Corsa Competizione\AC2\Binaries\Win64\AC2-Win64-Shipping.exe): Executable not found dxvk-nvapi:0308:0312:NvAPI_DRS_DestroySession: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_DestroySession: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10afb764/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_Initialize: Enter dxvk-nvapi:0308:0312:<-NvAPI_Initialize: OK dxvk-nvapi:0308:0312:NvAPI_DRS_CreateSession: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_CreateSession: OK dxvk-nvapi:0308:0312:NvAPI_DRS_LoadSettings: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_LoadSettings: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetBaseProfile: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetBaseProfile: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10afb76b/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_D3D11_CreateSamplerState: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_CreateSamplerState: OK dxvk-nvapi:0308:0312:NvAPI_D3D11_IsFatbinPTXSupported: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_IsFatbinPTXSupported(Supported): OK dxvk-nvapi:0308:0312:NvAPI_EnumPhysicalGPUs: Enter dxvk-nvapi:0308:0312:<-NvAPI_EnumPhysicalGPUs: OK dxvk-nvapi:0308:0312:NvAPI_GPU_GetAdapterIdFromPhysicalGpu: Enter dxvk-nvapi:0308:0312:<-NvAPI_GPU_GetAdapterIdFromPhysicalGpu: OK dxvk-nvapi:0308:0312:NvAPI_GPU_GetArchInfo: Enter dxvk-nvapi:0308:0312:<-NvAPI_GPU_GetArchInfo: OK dxvk-nvapi:0308:0312:NvAPI_D3D1x_GetGraphicsCapabilities: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D1x_GetGraphicsCapabilities: OK dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10afb76a/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_DRS_GetSetting: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_GetSetting (0x10afb76c/Unknown): Setting not found dxvk-nvapi:0308:0312:NvAPI_D3D11_CreateCubinComputeShaderWithName: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_CreateCubinComputeShaderWithName: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_EndUAVOverlap: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_EndUAVOverlap: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_BeginUAVOverlap: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_BeginUAVOverlap: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_SetDepthBoundsTest: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_SetDepthBoundsTest: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_CreateCubinComputeShaderWithName: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_CreateCubinComputeShaderWithName: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_CreateUnorderedAccessView: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_CreateUnorderedAccessView: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_GetResourceHandle: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_GetResourceHandle: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_GetResourceGPUVirtualAddressEx: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_GetResourceGPUVirtualAddressEx: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_GetResourceGPUVirtualAddress: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_GetResourceGPUVirtualAddress: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_CreateShaderResourceView: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_CreateShaderResourceView: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_GetCudaTextureObject: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_GetCudaTextureObject: OK dxvk-nvapi:0308:0836:NvAPI_D3D11_LaunchCubinShader: Enter dxvk-nvapi:0308:0836:<-NvAPI_D3D11_LaunchCubinShader: OK dxvk-nvapi:0308:0312:NvAPI_DRS_DestroySession: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_DestroySession: OK dxvk-nvapi:0308:0312:NvAPI_D3D11_DestroyCubinComputeShader: Enter dxvk-nvapi:0308:0312:<-NvAPI_D3D11_DestroyCubinComputeShader: OK dxvk-nvapi:0308:0312:NvAPI_DRS_DestroySession: Enter dxvk-nvapi:0308:0312:<-NvAPI_DRS_DestroySession: OK ```

• Added fixed prefix, PID, TID
• Log entering entrypoints
• Discard identical logging by thread
• Minor things found along the road (first two commits)

Logging enter/exit in pairs is not 100% procent whatertight, you wont find a pair when e.g. first call succeeded and second call failed. But imho still much better than what we had.

Closes #180

[jp7677]

mmh, the log statements are truncated in the proton logs. weird.

dxvvk-nvapi logs:

---------- 2024-05-31 17:03:45 ----------
dxvk-nvapi:0134:0138:NvAPI_QueryInterface (0xad298d3f): Unknown function ID
dxvk-nvapi:0134:0138:NvAPI_Initialize: Enter
dxvk-nvapi:0134:0138:DXVK-NVAPI v0.7.0-23-gde0e649 (AC2-Win64-Shipping.exe)
dxvk-nvapi:0134:0138:Successfully acquired Vulkan vkGetInstanceProcAddr @ 0x6ffffbc1d310
dxvk-nvapi:0134:0138:Successfully loaded nvml.dll
dxvk-nvapi:0134:0138:NVML loaded and initialized successfully
dxvk-nvapi:0134:0138:NvAPI Device: NVIDIA GeForce RTX 3090 (555.42.2)
dxvk-nvapi:0134:0138:NvAPI Output: \\.\DISPLAY1
dxvk-nvapi:0134:0138:<-NvAPI_Initialize: OK

proton log:

NvAPI_QueryInterface (0xad298d3f): Unknown function ID
NvAPI_Initialize: Enter
DXVK-NVAPI v0.7.0-23-gde0e649 (AC2-Win64-Shipping.exe)
1607.300:0134:0268:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-cs"
1607.300:0134:0138:fixme:system:NtUserQueryDisplayConfig flags 0x2, paths_count 0xb9bdf8, paths 0x14cf6d0, modes_count 0xb9bdfc, modes 0x14c50c0, topology_id (nil) semi-stub
1607.300:0134:0138:fixme:system:NtUserQueryDisplayConfig flags 0x2, paths_count 0xb9bdf8, paths 0x14cf6d0, modes_count 0xb9bdfc, modes 0x14c50c0, topology_id (nil) semi-stub
Successfully acquired Vulkan vkGetInstanceProcAddr @ 0x6ffffbc1d310
1607.301:0134:0138:trace:loaddll:build_module Loaded L"C:\\windows\\system32\\nvml.dll" at 00006FFFFBA30000: builtin
Successfully loaded nvml.dll
NVML loaded and initialized successfully
NvAPI Device: NVIDIA GeForce RTX 3090 (555.42.2)
1607.306:0134:0138:fixme:system:NtUserQueryDisplayConfig flags 0x2, paths_count 0xb9b628, paths 0x15241d0, modes_count 0xb9b62c, modes 0x14ba0f0, topology_id (nil) semi-stub
1607.306:0134:0138:fixme:system:NtUserQueryDisplayConfig flags 0x2, paths_count 0xb9820c, paths 0x15241d0, modes_count 0xb98270, modes 0x14c20c0, topology_id (nil) semi-stub
NvAPI Output: \\.\DISPLAY1
1607.307:0134:0138:fixme:system:NtUserQueryDisplayConfig flags 0x2, paths_count 0xb9b628, paths 0x15241d0, modes_count 0xb9b62c, modes 0x14c20c0, topology_id (nil) semi-stub
<-NvAPI_Initialize: OK

[Saancreed]

mmh, the log statements are truncated in the proton logs. weird.

Truncated? How so?

I can only see that all the prefix fluff isn't printed there but that's because only the part that writes to filestream prints them. The print function that actually forwards messages to Proton log via __wine_dbg_output only sees the final message part and is never asked to print any equivalent to what file log does.

[jp7677]

mmh, the log statements are truncated in the proton logs. weird.

Truncated? How so?

I can only see that all the prefix fluff isn't printed there but that's because only the part that writes to filestream prints them. The print function that actually forwards messages to Proton log via __wine_dbg_output only sees the final message part and is never asked to print any equivalent to what file log does.

ah of course, I was way to much focused on our file stream, need a cup of tea :)