Pipeline tracing

Abstract

How to enable pipeline tracing so that you can monitor or troubleshoot performance.

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:

  1. 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.

  2. To enable pipeline tracing, set "PipelineTraceLoggingEnabled" to true and LogLevel parameters to Debug.

    The following provides an example of logging configuration with pipeline tracing enabled:

    ...

"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
    },

  3. To view the trace log file, open the log file C:\inetpub\wwwroot\<CommerceShops_Sc9>\wwwroot\logs\<SCF.<YYYYMMDD>.log.<NODEGUID>.txt .

Note

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 :