Pipeline tracing
The pipeline framework provides tracing capability. Pipeline tracing allows you to monitor or troubleshoot the performance of individual custom or default Commerce pipelines and blocks, running on a given instance of a Commerce Engine. When you enable pipeline tracing, it saves trace data to the Commerce Engine node log. You can access the log file at the following location: C:\inetpub\wwwroot\<CommerceShops_Sc9>\wwwroot\logs\<SCF.<YYYYMMDD>.log.<NODEGUID>.txt
.
Enable pipeline tracing
Pipeline tracing is disabled by default.
To enable pipeline tracing:
-
Open the
config.json
file of the running Commerce Engine service where you want to trace pipelines. For example,C:\inetpub\wwwroot\<CommerceShops_Sc9>\wwwroot\config.json
. -
To enable pipeline tracing, set
"PipelineTraceLoggingEnabled"
totrue
andLogLevel
parameters toDebug
.The following provides an example of logging configuration with pipeline tracing enabled:
RequestResponseshell... "Logging": { "IncludeScopes": false, "LogLevel": { "Default": "Debug", "System": "Debug", "Microsoft": "Debug" }, "ApplicationInsightsLoggingEnabled": false, "PipelineTraceLoggingEnabled": true, "SerilogLoggingEnabled": true }, "Serilog": { "Using": [ "Serilog.Sinks.Literate", "Serilog.Sinks.File" ], "MinimumLevel": { "Default": "Debug", "Override": { "Microsoft": "Debug", "System": "Debug" } }, "FileSizeLimitBytes": 100000000 },
-
To view the trace log file, open the log file
C:\inetpub\wwwroot\<CommerceShops_Sc9>\wwwroot\logs\<SCF.<YYYYMMDD>.log.<NODEGUID>.txt
.
To disable pipeline tracing, set "PipelineTraceLoggingEnabled"
to false
.
Pipeline tracing log example
Pipeline tracing collects start time and end time information about a running pipeline and the blocks it executes. The following shows an example output of a pipeline trace log:
0024 11:23:08 DEBUG [PipelineStarted]
00024 11:23:08 DEBUG Block execution started for '"EntityVersions.block.SetEntityVersion"'
00024 11:23:08 DEBUG Block execution completed for '"EntityVersions.block.SetEntityVersion"'
00024 11:23:08 DEBUG Block execution started for '"Carts.Block.EnsureCartEntityUniqueId"'
00024 11:23:08 DEBUG Block execution completed for '"Carts.Block.EnsureCartEntityUniqueId"'
00024 11:23:08 DEBUG Block execution started for '"Core.block.EnsureEntityUniqueId"'
00024 11:23:08 DEBUG Block execution completed for '"Core.block.EnsureEntityUniqueId"'
00024 11:23:08 DEBUG Block execution started for '"Core.block.LoadVersioningEntity"'
00024 11:23:08 DEBUG Block execution completed for '"Core.block.LoadVersioningEntity"'
00024 11:23:08 DEBUG Block execution started for '"Customers.blocks.FindEntity"'
00024 11:23:08 DEBUG Block execution completed for '"Customers.blocks.FindEntity"'
00024 11:23:08 DEBUG Block execution started for '"Core.block.FindEntityInCache"'
00024 11:23:08 DEBUG Block execution completed for '"Core.block.FindEntityInCache"'
00024 11:23:08 DEBUG Block execution started for '"SQL:block:FindEntity"'
00024 11:23:08 DEBUG SQL.FindEntity.PolicySet: EntityId=Entity-PolicySet-CatalogPolicySet
00024 11:23:08 DEBUG Sharding policy for 'Entity-PolicySet-CatalogPolicySet', was not found.
00022 11:23:08 DEBUG Block execution completed for '"SQL:block:FindEntity"'
00022 11:23:08 DEBUG Block execution started for '"Core.block.CheckNegativeCache"'
00022 11:23:08 DEBUG Block execution completed for '"Core.block.CheckNegativeCache"'
00022 11:23:08 DEBUG Block execution started for '"Core.block.SetNegativeCache"'
00022 11:23:08 DEBUG Block execution completed for '"Core.block.SetNegativeCache"'
00022 11:23:08 DEBUG Block execution started for '"Core.block.DeserializeEntity"'
00022 11:23:08 DEBUG Block execution completed for '"Core.block.DeserializeEntity"'
00022 11:23:08 DEBUG Block execution started for '"Content.Block.EnsureContentItemChildren"'
00022 11:23:08 DEBUG Block execution completed for '"Content.Block.EnsureContentItemChildren"'
00022 11:23:08 DEBUG Block execution started for '"Core.block.SetEntityInCache"'
00022 11:23:08 DEBUG Block execution completed for '"Core.block.SetEntityInCache"'
00022 11:23:08 DEBUG Block execution started for '"Core.block.LoadEntityLocalizedValues"'
00022 11:23:08 DEBUG Block execution completed for '"Core.block.LoadEntityLocalizedValues"'
00022 11:23:08 DEBUG Block execution started for '"Core.block.CreateVersioningEntity"'
00022 11:23:08 DEBUG Block execution completed for '"Core.block.CreateVersioningEntity"'
00022 11:23:08 DEBUG [PipelineCompleted]
00022 11:23:08 DEBUG +-[ Pipeline Trace Output ]--------------------
00022 11:23:08 DEBUG |
00022 11:23:08 DEBUG | +[Pipeline] - 00:00:00.0116291 : Core.pipeline.findentity
00022 11:23:08 DEBUG | [00.85%] - 00:00:00.0000986 : Core.block.FindEntityInCache
00022 11:23:08 DEBUG | [01.07%] - 00:00:00.0001247 : Customers.blocks.FindEntity
00022 11:23:08 DEBUG | [00.75%] - 00:00:00.0000872 : Core.block.LoadVersioningEntity
00022 11:23:08 DEBUG | [00.92%] - 00:00:00.0001065 : Core.block.EnsureEntityUniqueId
00022 11:23:08 DEBUG | [00.64%] - 00:00:00.0000746 : Carts.Block.EnsureCartEntityUniqueId
00022 11:23:08 DEBUG | [00.95%] - 00:00:00.0001101 : EntityVersions.block.SetEntityVersion
00022 11:23:08 DEBUG | [88.81%] - 00:00:00.0103276 : SQL:block:FindEntity
00022 11:23:08 DEBUG | [00.57%] - 00:00:00.0000667 : Core.block.CreateVersioningEntity00022 11:23:08 DEBUG | [00.54%] - 00:00:00.0000623 :