Pipeline tracing

Current version: 10.1

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:

    RequestResponse
    ...
    
    "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:

RequestResponse
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 :

Do you have some feedback for us?

If you have suggestions for improving this article,