Logging in the Shared Source CLI 2.0

PAL Logging
- PAL Logging on Windows
Unified CLI Logging
Example Logging Sessions

There are several ways to turn on logging in the Shared Source Common Language Infrastructure (SSCLI) implementation. The two main categories of logging are:

Platform Adaptation Layer (PAL) logging.
- This is logging at a low level before calls are made to the operating system.
Unified CLI logging.
- This log processes in the SSCLI such as garbage collection, just-in-time (JIT) compilation, and so on.

PAL Logging

Note: It is safe to copy and use a checked or fastchecked build of the rotor_pal dynamic library in a retail build, so you can utilize API logging while running optimized binaries.

PAL Logging on Windows

Environment variable	Value	Description
PAL_API_TRACING	debugger	Sends log output to the debugger through OutputDebugString API. Note that from inside a debugger, if you modify the global variable rotor_pal!LogFileHandle from the default value of 0 to 0xffffffff, then logging will immediately begin to be output to the debugger. Setting the variable back to 0 will disable it again.
	filename	Sends log output to the specified filename.
	stderr	Sends log output to the standard error handler.
	stdout	Sends log output to the console.

Unified CLI Logging

The following environment variables can be set to enable detailed execution logging.

A unified logging system is used for garbage collection, JIT compilation, and other execution logging; the logging system is controlled by a set of variables. The implementation of the logging system is in %ROTOR_DIR%/clr/src/utilcode/log.cpp and %ROTOR_DIR%/clr/src/inc/log.h. Logging is enabled only in checked and fastchecked builds. If you want to change, this see the comment in log.cpp.

Environment variables have the same name as code variables but must be prefaced with "COMPlus_".

Every variable is read first from the environment, then from the per-user rotor.ini configuration file, and finally from the per-installation rotor.ini configuration file.

Some additional environment variables are used by the specific subsystem as described in the following table.

Environment variable	Value	Description
COMPlus_LogEnable	1	Enables logging. This value can be toggled on and off without changing the other options.
COMPlus_LogToConsole	1 One of these options must be set to 1 to enable logging output	Enables logging output to the console
COMPlus_LogToDebugger		Enables logging to the debugger (cordbg.exe)
COMPlus_LogToFile		Enables logging to a file
COMPlus_LogFile	Name of log file	Requires COMPlus_LogToFile=1
COMPlus_LogFlushFile		Flushes file buffers every time anything is logged. Applies to both LogToConsole and LogToFile. Slow but very reliable logging.
COMPlus_LogFileAppend	1	Appends to log file instead of replacing it.
COMPlus_LogLevel	n	Specifies the detail level of log output. n ranges from 1 to 9, where 1 is the least detailed log output and 9 is the most detailed log output.
COMPlus_LogFacility	bitmask_value	Hexadecimal bitmask of facilities log. Each bit represents one facility to log. The list of facilities is in sscli20/clr/src/inc/loglf.h Some useful settings for bitmask_value: 0x00000001 Log garbage collector activity. 0x00000008 Log JIT compilation activity. 0x12000003 Log garbage collector, live pointers, app domains, and security activity. For more details on this option, see the examples below.

JIT Compilation-Specific Logging Environment Variables

By default, these environment variables are operational only on checked or fastchecked builds.

Note: The COMPlus_JitDisasm variable that emits native code is not supported in the SSCLI. To obtain similar functionality, set COMPlus_JitBreak to the function you are interested in disassembling and then view the disassembled code in the debugger after the debugger breaks in that function.

Environment variable	Value	Description
COMPlus_JitName	LibraryName	Indicates the name of the JIT DLL library. If not defined, defaults to the hard-coded names mscorejt.dll on Microsoft® Windows® or libmscorejt.so on UNIX system-based platforms.
COMPlus_JitBreak	FunctionName	Breaks into the debugger before JIT-compiling FunctionName. Use the wildcard character * to JIT-compile all functions.
COMPlus_JitHalt	FunctionName	Emits a debugger break before the prolog of FunctionName. The inserted break occurs just before execution of the function. Use the wildcard character * to JIT-compile all functions.
COMPlus_JitTrace	0 1	If 1, prints out the trace of functions that were JIT-compiled. This trace output can also be obtained through the central logging system but this is a more lightweight mechanism that generates only JIT information.

Garbage Collection-Specific Logging Environment Variables

By default these are operational only on checked or fastchecked builds.

Environment Variable	Value	Description
COMPlus_GCprnLvl	detailnumber	Sets the level of detail of the logging output to detailnumber. The higher the number, the more data output.
COMPlus_GCtraceStart	startnumber	The garbage collection generation at which to start logging output.
COMPlus_GCtraceEnd	endnumber	The garbage collection generation at which to stop logging output.

Additional Logging Options

By default these are operational only on checked or fastchecked builds.

These options require that Unified CLI Logging be enabled but do not affect the other options set for Unified logging.

Environment variable	Value	Description
COMPlus_DumpOnClassLoad	classname	Dumps information about the classname class when it is loaded. The information that is dumped contains: Method table summary. Number of class static fields. Number of class instance fields. Number of class static object reference fields. Number of declared fields. Number of declared methods. A vtable dump. A field layout dump. A garbage collection descriptor dump.
COMPlus_JitCodeLog	FunctionName	Used only for JIT-compilation logging. Log JIT-compilation information for FunctionName. You can use FunctionName=* to log all functions

Environment variable

Value

Description

COMPlus_DumpOnClassLoad

classname

Dumps information about the classname class when it is loaded. The information that is dumped contains:

Method table summary.
Number of class static fields.
Number of class instance fields.
Number of class static object reference fields.
Number of declared fields.
Number of declared methods.
A vtable dump.
A field layout dump.
A garbage collection descriptor dump.

COMPlus_JitCodeLog

FunctionName

Used only for JIT-compilation logging.

Log JIT-compilation information for FunctionName.

You can use FunctionName=* to log all functions

Managed Code Logging Options

By default, these are operational only on checked or fastchecked builds.

These options require that Unified CLI Logging be enabled.

This functionality is defined in sscli20\clr\src\bcl\system\bcldebug.cs. To find locations where this logging facility is used, search for BCLDebug.Log in the sscli20\clr\src\bcl base class library source code files.

When using these logging functions it is recommended that you turn off logging for most unmanaged code facilities. For example, set COMPlus_LogFacility=1.

The COMPlus_LogLevel values are mapped for managed code logging to the following:

Loglevel	Mapping	Description
0	LogLevel.Panic	Logs panic asserts.
1	LogLevel.Error	Logs error asserts.
2	LogLevel.Error	Logs error asserts.
3	LogLevel.Warning	Logs warning asserts.
4	LogLevel.Warning	Logs warning asserts.
5	LogLevel.Status	Logs status-level output.
6	LogLevel.Status	Logs status-level output.
7	LogLevel.Trace	Logs all trace output. This is the highest degree of detail.
8	LogLevel.Trace	Logs all trace output. Same as 7.
9	LogLevel.Trace	Logs all trace output. Same as 7.

To see detailed output from the COMPlus_ManagedLogFacility setting requires having COMPlus_LogLevel set to 7, 8, or 9.

The following table contains additional environment variables used by the managed code logging implementation.

Environment variable	Value	Description
COMPlus_ManagedLogFacility	bitmask_value	Hexadecimal bitmask of facilities log. Each bit represents one facility to log. The settings for bitmask_value are:
		Mask Value	Switch Name	Description
		0x00000001	NLS	Traces globalization usage.
		0x00000002	SER	Traces serialization usage.
		0x00000004	DYNIL	Traces some Reflection.Emit usage.
		0x00000008	REMOTE	Traces remoting usage.
		0x00000010	BINARY	Traces binary formatter usage.
		0x00000020	SOAP	Traces soap formatter usage.
		0x00000040	REMOTINGCHANNELS	Traces remoting channels usage.
		0x00000080	CACHE	Traces reflection cache usage.
		0x00000100	RESMGRFILEFORMAT	Traces .resources file usage.
		0x00000200	PERF	Traces perf. Not used in SSCLI.
		0x00000400	CORRECTNESS	Traces correctness. Not used in SSCLI.

Example Logging Sessions

Garbage Collection Example

Environment

set COMPlus_LogEnable=1
set COMPlus_LogFacility=1
set COMPlus_LogToConsole=1
set COMPlus_LogToFile=0
set COMPlus_LogLevel=4

Application execution command.

This runs remoting tests.

clix tests\dev\remotingmarshal.exe

Log output that is sent to the console.

TID 013c: Executing program with command line 'tests\dev\remotingmarshal.exe'
TID 0160: Finalizer thread starting...{ =========== BEGINGC 0, (gen = 0, collect_classes = 0) ==========
TID 013c: WARNING: handle 00a213d8 causes pinning of object 01c03d50 System.Object[]
TID 013c: WARNING: handle 00a213dc causes pinning of object 01c03b28 System.Object[]
TID 013c: WARNING: handle 00a213e0 causes pinning of object 01c03900 System.Object[]
TID 013c: WARNING: handle 00a213e4 causes pinning of object 01c036d8 System.Object[]
TID 013c: WARNING: handle 00a213e8 causes pinning of object 01c034b0 System.Object[]
TID 013c: WARNING: handle 00a213ec causes pinning of object 01c03288 System.Object[]
TID 013c: WARNING: handle 00a213f0 causes pinning of object 01c01258 System.Object[]
TID 013c: WARNING: handle 00a213f4 causes pinning of object 01c01030 System.Object[]
TID 013c: WARNING: handle 00a213f8 causes pinning of object 00ccfa0c System.Object[C:\sscli20\binaries.x86chk.rotor\mscorlib.dll]
TID 013c: WARNING: handle 00a213fc causes pinning of object 01c00018 System.Object[]
TID 013c: WARNING: handle 037012fc causes pinning of object 01c02270 System.Object[]
TID 013c: ========== ENDGC (gen = 0, collect_classes = 0) ===========} Field setters succeeded
TID 013c: { =========== BEGINGC 1, (gen = 0, collect_classes = 0) ==========
TID 013c: ========== ENDGC (gen = 0, collect_classes = 0) ===========} Method invokes succeeded Field getters succeeded All test passed
TID 013c: Signalling finalizer to quit...Waiting for finalizer to quit...Finalizer thread done.

Security Example

Environment

set COMPlus_LogEnable=1
set COMPlus_LogFacility=0x10000000
set COMPlus_LogToConsole=1
set COMPlus_LogToFile=0
set COMPlus_LogLevel=6

Application execution command.

This runs StringBuilder and threadsafety tests.

clix tests\dev\remotingmarshal.exe

Log output that is sent to the console.

TID 0aec: Executing program with command line 'tests\dev\remotingmarshal.exe'
TID 0aec: No certificates found in module
TID 0aec: No certificates found in module
TID 0aec: No certificates found in module
TID 0aec: Code-access security check immediate invoked.
TID 0aec: Method: System.Security.CodeAccessSecurityEngine[C:\sscli20\binaries.x86chk. rotor\mscorlib.dll].CheckNReturnSO
TID 0aec: Method: System.Security.CodeAccessSecurityEngine[C:\sscli20\binaries.x86chk. rotor\mscorlib.dll].Assert
TID 0aec: Method: System.Security.CodeAccessPermission[C:\sscli20\binaries.x86chk.roto r\mscorlib.dll].Assert
TID 0aec: Method: System.Runtime.Serialization.Formatters.Binary.ObjectReader[C:\sscli 20\binaries.x86chk.rotor\mscorlib.dll].FastBindToType
TID 0aec: Code-access stackwalk completed.
TID 0aec: Code-access security check immediate invoked.
TID 0aec: Method: System.Security.CodeAccessSecurityEngine[C:\sscli20\binaries.x86chk. rotor\mscorlib.dll].CheckNReturnSO
TID 0aec: Method: System.Security.CodeAccessSecurityEngine[C:\sscli20\binaries.x86chk. rotor\mscorlib.dll].Assert
TID 0aec: Method: System.Security.CodeAccessPermission[C:\sscli20\binaries.x86chk.roto r\mscorlib.dll].Assert
TID 0aec: Method: System.Runtime.Serialization.Formatters.Binary.ObjectReader[C:\sscli 20\binaries.x86chk.rotor\mscorlib.dll].FastBindToType
TID 0aec: Code-access stackwalk completed.
TID 0aec: Code-access security check immediate invoked.
TID 0aec: Method: System.Security.CodeAccessSecurityEngine[C:\sscli20\binaries.x86chk. rotor\mscorlib.dll].CheckNReturnSOLoader Example
...

JitCodeLog=Main Example: LogLevel=4

Environment

Entry and exit logging for JIT-compiling in the prolog and epilog sections, and in exception handlers

set COMPlus_JitCodeLog=Main
set COMPlus_LogEnable=1
set COMPlus_LogFacility=0x00000008
set COMPlus_LogToConsole=1
set COMPlus_LogToFile=0
set COMPlus_LogLevel=4

Application execution command.

This runs the try and finally tests.

clix tests\bvt\short\CS_TryFinally.exe

Log output that is sent to the console.

TID 12cc: Executing program with command line 'cs_tryfinally.exe'
TID 12cc: Fjitted 'CO_TryFinally::Main' at addr 0x375c2b8 to 0x375cb4c header 0
TID 12cc: { entering CO_TryFinally::Main 1:
Abort( )
1: finally 1
1: finally 2
1: finally 3
1: finally 4
1: finally 5
1: finally 6
1: finally 7
1: finally 8
2: Abort( )
2: finally 8
2: finally 7
2: finally 6
2: finally 5
2: finally 4
2: finally 3
2: finally 2
2: finally 1
3: Abort( )
3: finally 1
TID 12cc: }
leaving TextWriter::Main JitCodeLog=Main Example: LogLevel=5

Environment

set COMPlus_JitCodeLog=Main
set COMPlus_LogEnable=1
set COMPlus_LogFacility=0x00000008
set COMPlus_LogToConsole=1
set COMPlus_LogToFile=0
set COMPlus_LogLevel=5

Garbage collection map information is printed describing the locals and the arguments.

Logging code fragments describing the state of the processor are inserted after code for each intermediate language (IL) instruction.

Application execution command.

This runs the try and finally tests.

clix tests\bvt\short\CS_TryFinally.exe

Log output that is sent to the console.

TID 10ec: Executing program with command line 'cs_tryfinally.exe'
TID 10ec: Request new LoaderCodeHeap::CreateCodeHeap(00010000, 00000000, for domain 7965a3 48 in 00000000 .. 00000000 )
TID 10ec: Created new CodeHeap( 0375005c .. 03760000 )
TID 10ec: ********* GC map info *******
TID 10ec: Locals: (Length = 0x5, Frame size = 0x18)
TID 10ec: local 0: offset: -0x18 type: typeRef
TID 10ec: local 1: offset: -0x1c type: typeRef
TID 10ec: local 2: offset: -0x20 type: typeRef
TID 10ec: local 3: offset: -0x24 type: typeRef
TID 10ec: local 4: offset: -0x28 type: typeI4
TID 10ec: Bitvectors printed low bit (low local), first
TID 10ec: LocalsGCRef bit vector len=4 bits: 1 1 1 1
TID 10ec: interiorGC bitvector len=0 bits:
TID 10ec: Pinned LocalsGCRef bit vector: len=0 bits:
TID 10ec: Pinned interiorGC bit vector len =0 bits:
TID 10ec: Args: (Length = 0x1, Frame size = 0)
TID 10ec: offset: -0xc type: typeRef
TID 10ec: Fjitted 'CO_TryFinally::Main' at addr 0x375c2b8 to 0x375cb4c header 0
TID 10ec: { entering CO_TryFinally::Main
TID 10ec: ESP: 1ae89c[ 0: 0: 0] EBP: 1ae8c4 IL: 0 nop
TID 10ec: ESP: 1ae89c[ 0: 0: 0] EBP: 1ae8c4 IL: 1 newobj
TID 10ec: ESP:+ 1ae898[ cd21c8: 0: 0] EBP: 1ae8c4 IL: 6 stloc.0
TID 10ec: ESP: 1ae89c[ 0: 0: 0] EBP: 1ae8c4 IL: 7 ldloc.0
TID 10ec: ESP:+ 1ae898[ cd21c8: 0: 0] EBP: 1ae8c4 IL: 8 ldftn
TID 10ec: ESP:+ 1ae894[ a42fc8: cd21c8: 0] EBP: 1ae8c4 IL: e newobj
TID 10ec: ESP:+ 1ae898[ cd21d8: 0: 0] EBP: 1ae8c4 IL: 13 newobj
TID 10ec: ESP:+ 1ae898[ cd21f8: 0: 0] EBP: 1ae8c4 IL: 18 stloc.1
TID 10ec: ESP: 1ae89c[ 0: 0: 0] EBP: 1ae8c4 IL: 19 ldloc.0
TID 10ec: ESP:+ 1ae898[ cd21c8: 0: 0] EBP: 1ae8c4 IL: 1a ldftn
TID 10ec: ESP:+ 1ae894[ a42fe8: cd21c8: 0] EBP: 1ae8c4 IL: 20 newobj
TID 10ec: ESP:+ 1ae898[ cd229c: 0: 0] EBP: 1ae8c4 IL: 25 newobj
TID 10ec: ESP:+ 1ae898[ cd22bc: 0: 0] EBP: 1ae8c4 IL: 2a stloc.2
TID 10ec: ESP: 1ae89c[ 0: 0: cd22bc] EBP: 1ae8c4 IL: 2b ldloc.0
TID 10ec: ESP:+ 1ae898[ cd21c8: 0: 0] EBP: 1ae8c4 IL: 2c ldftn
TID 10ec: ESP:+ 1ae894[ a43008: cd21c8: 0] EBP: 1ae8c4 IL: 32 newobj
TID 10ec: ESP:+ 1ae898[ cd2324: 0: 0] EBP: 1ae8c4 IL: 37 newobj
TID 10ec: ESP:+ 1ae898[ cd2344: 0: 0] EBP: 1ae8c4 IL: 3c stloc.3
TID 10ec: ESP: 1ae89c[ 0: cd2344: cd22bc] EBP: 1ae8c4 IL: 3d ldloc.1
TID 10ec: ESP:+ 1ae898[ cd21f8: 0: cd2344] EBP: 1ae8c4 IL: 3e callvirt
...

Environment

set COMPlus_JitCodeLog=Main
set COMPlus_LogEnable=1
set COMPlus_LogFacility=0x00000008
set COMPlus_LogToConsole=1
set COMPlus_LogToFile=0
set COMPlus_LogLevel=6

Application execution command.

This runs the try and finally tests.

clix tests\bvt\short\CS_TryFinally.exe

Log output that is sent to the console.

Too much output to list. With this log level setting the stack states encoded for garbage collection are output.

Logging in the Shared Source CLI 2.0

Contents

PAL Logging

PAL Logging on Windows

Unified CLI Logging

JIT Compilation-Specific Logging Environment Variables

Garbage Collection-Specific Logging Environment Variables

Additional Logging Options

Managed Code Logging Options

Example Logging Sessions

Garbage Collection Example

Environment

Application execution command.

Log output that is sent to the console.

Security Example

Environment

Application execution command.

Log output that is sent to the console.

JitCodeLog=Main Example: LogLevel=4

Environment

Application execution command.

Log output that is sent to the console.

Environment

Application execution command.

Log output that is sent to the console.

Environment

Application execution command.

Log output that is sent to the console.