search

microsoft / ApplicationInsights-Profiler-AspNetCore

Application Insights Profiler sample and documentation
MIT License
66 stars 24 forks source link

Profiler seems not working under docker #89

Closed spike008t closed 3 years ago

spike008t commented 4 years ago

I'm trying to make Profiler works under docker. I actually using the latest dotnet/core/sdk:3.1-alpine docker image. I'm actually using the latest packages available (based on dotnet list packages command):

   [netcoreapp3.1]: 
   Top-level Package                                           Requested   Resolved   
   > IdentityServer4                                           3.1.2       3.1.2      
   > IdentityServer4.AccessTokenValidation                     3.0.1       3.0.1      
   > IdentityServer4.AspNetIdentity                            3.1.2       3.1.2      
   > IdentityServer4.EntityFramework                           3.1.2       3.1.2      
   > MailKit                                                   2.6.0       2.6.0      
   > Microsoft.ApplicationInsights.AspNetCore                  2.13.1      2.13.1     
   > Microsoft.ApplicationInsights.Profiler.AspNetCore         2.1.0-*     2.1.0-beta4
   > Microsoft.AspNetCore.Authentication.Google                3.1.3       3.1.3      
   > Microsoft.AspNetCore.Authentication.JwtBearer             3.1.3       3.1.3      
   > Microsoft.AspNetCore.Authentication.MicrosoftAccount      3.1.3       3.1.3      
   > Microsoft.AspNetCore.Diagnostics.EntityFrameworkCore      3.1.3       3.1.3      
   > Microsoft.AspNetCore.Identity.EntityFrameworkCore         3.1.3       3.1.3      
   > Microsoft.AspNetCore.Identity.UI                          3.1.3       3.1.3      
   > Microsoft.AspNetCore.Mvc.NewtonsoftJson                   3.1.3       3.1.3      
   > Microsoft.AspNetCore.Mvc.Razor.RuntimeCompilation         3.1.3       3.1.3      
   > Microsoft.EntityFrameworkCore.Design                      3.1.3       3.1.3      
   > Microsoft.EntityFrameworkCore.SqlServer                   3.1.3       3.1.3      
   > Microsoft.EntityFrameworkCore.Tools                       3.1.3       3.1.3      
   > Microsoft.IdentityModel.Protocols.OpenIdConnect           5.6.0       5.6.0      
   > Microsoft.VisualStudio.Web.CodeGeneration.Design          3.1.1       3.1.1      
   > Pomelo.EntityFrameworkCore.MySql                          3.1.1       3.1.1      
   > Sendgrid                                                  9.12.6      9.12.6     
   > Serilog.AspNetCore                                        3.2.0       3.2.0      
   > Serilog.Sinks.Console                                     3.1.1       3.1.1      
   > Serilog.Sinks.ElkStreams                                  1.2.7       1.2.7      
   > Serilog.Sinks.File                                        4.1.0       4.1.0      
   > Swashbuckle.AspNetCore                                    5.3.2       5.3.2      
   > Swashbuckle.AspNetCore.Annotations                        5.3.2       5.3.2      
   > Twilio                                                    5.37.3      5.37.3     
   > Wangkanai.Detection                                       2.0.0       2.0.0      
   > Westwind.AspNetCore.Markdown                              3.3.6       3.3.6

The debug output when running the docker image locally:

[00:40:28 Debug] ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30
Sample is added: {"StartActivityIdPath":"/#40/1/35/1/","StopActivityIdPath":"/#40/1/35/1/","StartTimeUtc":"2020-06-05T00:40:26.305055+00:00","StopTimeUtc":"2020-06-05T00:40:28.4206881+00:00","RequestId":"2aa2b8ce77e85f47","RoleInstance":"2eea63205d9f","OperationName":"GET Administration/Index","OperationId":"95abc3a41db6c64b9ec3775caad60379","Duration":"00:00:02.1185719"}

[00:40:28 Debug] ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30
Sample is added: {"StartActivityIdPath":"/#40/1/36/1/","StopActivityIdPath":"/#40/1/36/1/","StartTimeUtc":"2020-06-05T00:40:28.7776561+00:00","StopTimeUtc":"2020-06-05T00:40:28.793982+00:00","RequestId":"2a0dc6f570c94e46","RoleInstance":"2eea63205d9f","OperationName":"GET /images/faces/generic.jpg","OperationId":"d7a54240f01b9745ab668035d1af7297","Duration":"00:00:00.0163378"}

[00:40:28 Debug] ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30
Sample is added: {"StartActivityIdPath":"/#40/1/37/1/","StopActivityIdPath":"/#40/1/37/1/","StartTimeUtc":"2020-06-05T00:40:28.7777826+00:00","StopTimeUtc":"2020-06-05T00:40:28.7967514+00:00","RequestId":"1b6403d4ac9c6b4f","RoleInstance":"2eea63205d9f","OperationName":"GET /js/site.min.js","OperationId":"7cee2c428574f246ac139dd99358aa49","Duration":"00:00:00.0189736"}

[00:40:49 Debug] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Entering StopServiceProfilerAsync.

[00:40:49 Debug] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Disabling SessionListener

[00:40:49 Debug] ServiceProfiler.EventPipe.Client.TraceControls.TraceControl
Disabling EventPipe . . .

[00:40:50 Debug] ServiceProfiler.EventPipe.Client.TraceControls.TraceControl
EventPipe disabled.

[00:40:50 Debug] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Entering PostStopProcessAsync

[00:40:50 Debug] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
There are 17 samples before validation.

[00:40:50 Debug] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Start to validate trace.

[00:40:52 Error] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Expected trace validation error.
ServiceProfiler.EventPipe.Client.TraceValidators.ValidateFailedException: [ActivityListValidator] No sample activity matches the trace.
   at ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator.ValidateImp(IEnumerable`1 samples)
   at ServiceProfiler.EventPipe.Client.TraceValidators.TraceValidatorBase.Validate(IEnumerable`1 samples)
   at ServiceProfiler.EventPipe.Client.TraceValidators.TraceValidatorBase.Validate(IEnumerable`1 samples)
   at ServiceProfiler.EventPipe.Client.ServiceProfilerProvider.ValidateSamples(String traceFilePath, List`1 samples)

[00:40:52 Debug] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Finished validate the trace.

[00:40:52 Information] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Trace validation result: False

[00:40:52 Warning] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Trace validation failed. Upload aborted and no customer events released.

[00:40:53 Information] ServiceProfiler.EventPipe.Client.ServiceProfilerProvider
Service Profiler session finished.

Any idea how to make it works under docker container? And why the validation failed? (the aim is to deploy it on an azure app service for container).

Thank you

saurabhpati commented 4 years ago

facing same issue for dotnet core 2.2, mcr.microsoft.com/dotnet/core/sdk:2.2

I have tried adding this in the docker file:

RUN dotnet add <ProjectName> package Microsoft.ApplicationInsights.Profiler.AspNetCore -v 2.1.0-beta4

ARG APPINSIGHTS_KEY
# Making sure the argument is set. Fail the build of the container otherwise.
RUN test -n "$APPINSIGHTS_KEY"

# Light up Application Insights and Service Profiler
ENV APPINSIGHTS_INSTRUMENTATIONKEY $APPINSIGHTS_KEY
ENV ASPNETCORE_HOSTINGSTARTUPASSEMBLIES Microsoft.ApplicationInsights.Profiler.AspNetCore

and relevant argument in docker-compose.yml

 build:
   args:
        APPINSIGHTS_KEY: "<InstrumentationKey>"
xiaomi7732 commented 4 years ago

@spike008t, I'll take a look.

xiaomi7732 commented 4 years ago

Hi @spike008t , I tried a simple webapi on alpine and it looks like it worked for me. Could you please turn on Trace logs and run it again and send over the logs for analysis?

My logs just FYI:

dbug: ServiceProfiler.EventPipe.AspNetCore.ConfigureUserConfiguration[0]
      Configure user configuration.
trce: ServiceProfiler.EventPipe.AspNetCore.ConfigureUserConfiguration[0]
      {
        "BufferSizeInMB": 250,
        "Duration": "00:00:30",
        "InitialDelay": "00:00:00",
        "ConfigurationUpdateFrequency": "00:00:05",
        "ProvideAnonymousTelemetry": true,
        "IsDisabled": false,
        "RandomProfilingOverhead": 0.05,
        "IsSkipCompatibilityTest": false,
        "Endpoint": null,
        "SkipUpload": false,
        "PreserveTraceFile": false,
        "SkipEndpointCertificateValidation": false,
        "CPUTriggerThreshold": 80.0,
        "MemoryTriggerThreshold": 80.0,
        "StandaloneMode": false
      }
dbug: ServiceProfiler.EventPipe.AspNetCore.ServiceProfilerStartupFilter[0]
      Constructing ServiceProfilerStartupFilter
dbug: ServiceProfiler.EventPipe.AspNetCore.ConfigureUserConfiguration[0]
      Configure user configuration.
trce: ServiceProfiler.EventPipe.AspNetCore.ConfigureUserConfiguration[0]
      {
        "BufferSizeInMB": 250,
        "Duration": "00:00:30",
        "InitialDelay": "00:00:00",
        "ConfigurationUpdateFrequency": "00:00:05",
        "ProvideAnonymousTelemetry": true,
        "IsDisabled": false,
        "RandomProfilingOverhead": 0.05,
        "IsSkipCompatibilityTest": false,
        "Endpoint": null,
        "SkipUpload": false,
        "PreserveTraceFile": false,
        "SkipEndpointCertificateValidation": false,
        "CPUTriggerThreshold": 80.0,
        "MemoryTriggerThreshold": 80.0,
        "StandaloneMode": false
      }
dbug: ServiceProfiler.EventPipe.AspNetCore.ServiceProfilerStartupFilter[0]
      User Settings:
      {
        "BufferSizeInMB": 250,
        "Duration": "00:00:30",
        "InitialDelay": "00:00:00",
        "ConfigurationUpdateFrequency": "00:00:05",
        "ProvideAnonymousTelemetry": true,
        "IsDisabled": false,
        "RandomProfilingOverhead": 0.05,
        "IsSkipCompatibilityTest": false,
        "Endpoint": null,
        "SkipUpload": false,
        "PreserveTraceFile": false,
        "SkipEndpointCertificateValidation": false,
        "CPUTriggerThreshold": 80.0,
        "MemoryTriggerThreshold": 80.0,
        "StandaloneMode": false
      }
trce: ServiceProfiler.EventPipe.AspNetCore.ServiceProfilerStartupFilter[0]
      Starting service profiler from application builder.
dbug: ServiceProfiler.EventPipe.AspNetCore.ServiceProfilerStartupFilter[0]
      Pass Runtime Compatibility test.
info: ServiceProfiler.EventPipe.AspNetCore.ServiceProfilerStartupFilter[0]
      Starting application insights profiler with instrumentation key: redacted
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.ResourceUsageSource[0]
      CPU Triggering settings: {
        "Enabled": true,
        "CpuThreshold": 80.0,
        "CpuAverageWindow": 30,
        "CpuRollingHistorySize": 10,
        "CpuRollingHistoryInterval": 30,
        "CpuTriggerCooldownInSeconds": 14400,
        "CpuTriggerProfilingDurationInSeconds": 120
      }
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.ResourceUsageSource[0]
      Memory Triggering settings: {
        "Enabled": true,
        "MemoryThreshold": 80.0,
        "MemoryAverageWindow": 30,
        "MemoryRollingHistorySize": 10,
        "MemoryRollingHistoryInterval": 30,
        "MemoryTriggerCooldownInSeconds": 14400,
        "MemoryTriggerProfilingDurationInSeconds": 120
      }
dbug: Microsoft.ServiceProfiler.Orchestration.MetricsProviders.MemInfoFileMemoryMetricsProvider[0]
      Get memory usage: free/total: 8974912/12995964
dbug: Microsoft.ServiceProfiler.Orchestration.MetricsProviders.MemInfoFileMemoryMetricsProvider[0]
      Get memory usage: free/total: 8974912/12995964
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe[0]
      Starting the orchestrator.
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe[0]
      5 scheduling policies has been activated.
dbug: Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy[0]
      Scheduling Policy: OneTimeSchedulingPolicy requesting StartProfilingSession for 00:00:30
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Entering StartServiceProfilerAsync.
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Got the semaphore. Try starting the Profiler.
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Trace: /tmp/b438e128-2fba-4e24-847a-bdfb2600699d.netperf
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Call TraceControl.Enable().
trce: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Trace Configuration:
      ===============================
      {
        "TraceProviders": [
          {
            "Name": "Microsoft-Windows-DotNETRuntime",
            "ProviderGuid": "e13c0d23-ccbc-4e12-931b-d9cc2eee27e4",
            "Keyword": 20423101629,
            "Level": 5
          },
          {
            "Name": "Microsoft-Windows-DotNETRuntimePrivate",
            "ProviderGuid": "763fd754-7086-4dfe-95eb-c01a46faf4ca",
            "Keyword": 1073872907,
            "Level": 5
          },
          {
            "Name": "Microsoft-DotNETCore-SampleProfiler",
            "ProviderGuid": "3c530d44-97ae-513a-1e6d-783e8f8e03a9",
            "Keyword": 0,
            "Level": 5
          },
          {
            "Name": "System.Threading.Tasks.TplEventSource",
            "ProviderGuid": "2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5",
            "Keyword": 199,
            "Level": 5
          },
          {
            "Name": "Microsoft-ApplicationInsights-DataRelay",
            "ProviderGuid": "8206c581-c6a3-550a-af53-6e0421740cbe",
            "Keyword": 4294967295,
            "Level": 5
          }
        ],
        "TraceFilePath": "/tmp/b438e128-2fba-4e24-847a-bdfb2600699d.netperf",
        "CircularBufferMB": 250
      }
      ===============================
dbug: ServiceProfiler.EventPipe.Client.TraceControls.TraceControl[0]
      Enabling EventPipe . . .
trce: ServiceProfiler.EventPipe.Client.TraceControls.TraceControl[0]
      Step1. Turning build the configuration, turning on the event sources
trce: ServiceProfiler.EventPipe.Client.TraceControls.TraceControl[0]
      Step2. Turn on EventPipe by calling into the Reflected method.
dbug: ServiceProfiler.EventPipe.Client.TraceControls.TraceControl[0]
      EventPipe enabled.
info: Microsoft.Hosting.Lifetime[0]
      Now listening on: http://[::]:80
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /app
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Start to create trace session listenter by its factory
dbug: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      [2020-06-12T00:42:16.9241567+00:00] Enabling EventSource: Microsoft-ApplicationInsights-Data
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Activating trace session listener: TraceSessionListener30
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      TraceSessionListener created.
info: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Service Profiler session started.
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe[0]
      Profiling is started. Source: OneTimeSchedulingPolicy
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 30
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 0
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: RemoteDependency, Keywords: 16, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1024, OpCode: Start
warn: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware[3]
      Failed to determine the https port for redirect.
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 0
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 30
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: RemoteDependency, Keywords: 16, OpCode: Info
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 0
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 30
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1024, OpCode: Stop
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1, OpCode: Info
dbug: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      Sample is added: {"StartActivityIdPath":"/#1/1/1/1/","StopActivityIdPath":"/#1/1/1/1/","StartTimeUtc":"2020-06-12T00:42:20.0284254+00:00","StopTimeUtc":"2020-06-12T00:42:27.1162825+00:00","RequestId":"e74667273125944c","RoleInstance":"c5e2cdd6ce11","OperationName":"GET WeatherForecast/Get","OperationId":"0bfe53e8e1f7f643af71844d23b74dc6","Duration":"00:00:07.0966571"}
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: RemoteDependency, Keywords: 16, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1024, OpCode: Start
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 0
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 30
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: RemoteDependency, Keywords: 16, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1024, OpCode: Stop
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1, OpCode: Info
dbug: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      Sample is added: {"StartActivityIdPath":"/#1/1/4/1/","StopActivityIdPath":"/#1/1/4/1/","StartTimeUtc":"2020-06-12T00:42:28.9602809+00:00","StopTimeUtc":"2020-06-12T00:42:34.4125282+00:00","RequestId":"8b63f99ddc299145","RoleInstance":"c5e2cdd6ce11","OperationName":"GET WeatherForecast/Get","OperationId":"34fd1956619e3e43a047c1bc41dcc74a","Duration":"00:00:05.4520986"}
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1024, OpCode: Start
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 0
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 30
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: RemoteDependency, Keywords: 16, OpCode: Info
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 0
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 30
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: RemoteDependency, Keywords: 16, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1024, OpCode: Stop
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Request, Keywords: 1, OpCode: Info
dbug: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      Sample is added: {"StartActivityIdPath":"/#1/1/6/1/","StopActivityIdPath":"/#1/1/6/1/","StartTimeUtc":"2020-06-12T00:42:36.5480114+00:00","StopTimeUtc":"2020-06-12T00:42:45.4424048+00:00","RequestId":"d05e203497ae8d48","RoleInstance":"c5e2cdd6ce11","OperationName":"GET WeatherForecast/Get","OperationId":"fb564b502a4a8a4186ac8843ad3ba944","Duration":"00:00:08.8945695"}
dbug: Microsoft.ServiceProfiler.Orchestration.MetricsProviders.MemInfoFileMemoryMetricsProvider[0]
      Get memory usage: free/total: 8680512/12995964
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.OrchestratorEventPipe[0]
      Stopping Profiler by OneTimeSchedulingPolicy
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
trce: ServiceProfiler.EventPipe.Client.EventListeners.TraceSessionListener30[0]
      OnRichPayloadEventWritten - EventName: Message, Keywords: 2, OpCode: Info
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Entering StopServiceProfilerAsync.
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Disabling SessionListener
dbug: ServiceProfiler.EventPipe.Client.TraceControls.TraceControl[0]
      Disabling EventPipe . . .
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 1
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 32
dbug: ServiceProfiler.EventPipe.Client.TraceControls.TraceControl[0]
      EventPipe disabled.
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Entering PostStopProcessAsync
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      There are 3 samples before validation.
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Start to validate trace.
trce: ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator[0]
      [00:42:48] Hit on: /#1/1/1/1/. OpCode: Start, IsStartHit: True, IsStopHit: False
trce: ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator[0]
      [00:42:48] Hit on: /#1/1/1/1/. OpCode: Stop, IsStartHit: True, IsStopHit: True
trce: ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator[0]
      [00:42:48] Hit on: /#1/1/4/1/. OpCode: Start, IsStartHit: True, IsStopHit: False
trce: ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator[0]
      [00:42:48] Hit on: /#1/1/4/1/. OpCode: Stop, IsStartHit: True, IsStopHit: True
trce: ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator[0]
      [00:42:48] Hit on: /#1/1/6/1/. OpCode: Start, IsStartHit: True, IsStopHit: False
trce: ServiceProfiler.EventPipe.Client.TraceValidators.ActivityListValidator[0]
      [00:42:48] Hit on: /#1/1/6/1/. OpCode: Stop, IsStartHit: True, IsStopHit: True
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Finished validate the trace.
info: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Trace validation result: True
trce: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Trace session finished. Invoking upload. Args:
      {
        "TraceFilePath": "/tmp/b438e128-2fba-4e24-847a-bdfb2600699d.netperf",
        "SessionId": "2020-06-12T00:42:16.887004+00:00",
        "StampFrontendHostUrl": "https://agent.azureserviceprofiler.net",
        "Samples": [
          {
            "StartActivityIdPath": "/#1/1/6/1/",
            "StopActivityIdPath": "/#1/1/6/1/",
            "StartTimeUtc": "2020-06-12T00:42:36.5480114+00:00",
            "StopTimeUtc": "2020-06-12T00:42:45.4424048+00:00",
            "RequestId": "d05e203497ae8d48",
            "RoleInstance": "c5e2cdd6ce11",
            "OperationName": "GET WeatherForecast/Get",
            "OperationId": "fb564b502a4a8a4186ac8843ad3ba944",
            "Duration": "00:00:08.8945695"
          },
          {
            "StartActivityIdPath": "/#1/1/4/1/",
            "StopActivityIdPath": "/#1/1/4/1/",
            "StartTimeUtc": "2020-06-12T00:42:28.9602809+00:00",
            "StopTimeUtc": "2020-06-12T00:42:34.4125282+00:00",
            "RequestId": "8b63f99ddc299145",
            "RoleInstance": "c5e2cdd6ce11",
            "OperationName": "GET WeatherForecast/Get",
            "OperationId": "34fd1956619e3e43a047c1bc41dcc74a",
            "Duration": "00:00:05.4520986"
          },
          {
            "StartActivityIdPath": "/#1/1/1/1/",
            "StopActivityIdPath": "/#1/1/1/1/",
            "StartTimeUtc": "2020-06-12T00:42:20.0284254+00:00",
            "StopTimeUtc": "2020-06-12T00:42:27.1162825+00:00",
            "RequestId": "e74667273125944c",
            "RoleInstance": "c5e2cdd6ce11",
            "OperationName": "GET WeatherForecast/Get",
            "OperationId": "0bfe53e8e1f7f643af71844d23b74dc6",
            "Duration": "00:00:07.0966571"
          }
        ],
        "IsTraceValid": true,
        "ProfilerSource": "OneTimeSchedulingPolicy"
      }
trce: ServiceProfiler.EventPipe.Client.TraceUploader.TraceUploaderProxy[0]
      uploaderPath by expand environment var of %SP_UPLOADER_PATH%: %SP_UPLOADER_PATH%
dbug: ServiceProfiler.EventPipe.Client.TraceUploader.TraceUploaderProxy[0]
      Environment variable of %SP_UPLOADER_PATH% is not set. Falls back to default path.
dbug: ServiceProfiler.EventPipe.Client.TraceUploader.TraceUploaderProxy[0]
      Searching for trace uploader at /app/ServiceProfiler/Microsoft.ApplicationInsights.Profiler.Uploader.dll
dbug: ServiceProfiler.EventPipe.Client.UploaderCallers.UploaderLocator[0]
      Locating file path with input: /app/ServiceProfiler/Microsoft.ApplicationInsights.Profiler.Uploader.dll
dbug: ServiceProfiler.EventPipe.Client.UploaderCallers.UploaderLocator[0]
      File uploader is not found. Try the zip file: /app/ServiceProfiler/TraceUpload.zip
dbug: ServiceProfiler.EventPipe.Client.UploaderCallers.UploaderLocator[0]
      Zip file exist. Unzipping . . .
dbug: ServiceProfiler.EventPipe.Client.UploaderCallers.UploaderLocator[0]
      File uploader is found: /app/ServiceProfiler/Microsoft.ApplicationInsights.Profiler.Uploader.dll
dbug: ServiceProfiler.EventPipe.Client.UploaderCallers.OutOfProcCaller[0]
      Calling execute out of proc on dotnet with arguments: /app/ServiceProfiler/Microsoft.ApplicationInsights.Profiler.Uploader.dll -t "/tmp/b438e128-2fba-4e24-847a-bdfb2600699d.netperf" -i redacted -d e54708db-77b6-457e-b577-103e84229f2c --sessionId "2020-06-12T00:42:16.8870040Z" -s "eastus-kdhwlf5sz6p6s" --host https://agent.azureserviceprofiler.net --metadata "/tmp/b438e128-2fba-4e24-847a-bdfb2600699d.metadata"
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 32
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 1
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.CPUMonitoringSchedulingPolicy[0]
      CPU Usage: 1
dbug: Microsoft.ServiceProfiler.EventPipe.Orchestration.MemoryMonitoringSchedulingPolicy[0]
      Memory Usage: 32
info: ServiceProfiler.EventPipe.Client.TraceUploader.TraceUploaderProxy[0]
      Finished calling trace uploader. Exit code: 0
dbug: ServiceProfiler.EventPipe.Client.ServiceProfilerProvider[0]
      Sending 3 valid custom events to AI.
dbug: ServiceProfiler.EventPipe.Client.SampleTransfers.CustomEventsTracker[0]
      Start to send samples to AI.
trce: ServiceProfiler.EventPipe.Client.SampleTransfers.CustomEventsTracker[0]
      [2020-06-12T00:42:59.9228417+00:00] Sending custom event to AI: 
      {
        "RequestId": "d05e203497ae8d48",
        "ServiceProfilerVersion": "v2",
        "ServiceProfilerContent": "v1|eastus-kdhwlf5sz6p6s|e54708db-77b6-457e-b577-103e84229f2c|c5e2cdd6ce11|1|2020-06-12T00:42:16.8870040Z|/#1/1/6/1/|2020-06-12T00:42:36.5480114Z|2020-06-12T00:42:45.4424048Z"
      }.
      iKey: redacted.
trce: ServiceProfiler.EventPipe.Client.SampleTransfers.CustomEventsTracker[0]
      [2020-06-12T00:42:59.9261169+00:00] Sending custom event to AI: 
      {
        "RequestId": "8b63f99ddc299145",
        "ServiceProfilerVersion": "v2",
        "ServiceProfilerContent": "v1|eastus-kdhwlf5sz6p6s|e54708db-77b6-457e-b577-103e84229f2c|c5e2cdd6ce11|1|2020-06-12T00:42:16.8870040Z|/#1/1/4/1/|2020-06-12T00:42:28.9602809Z|2020-06-12T00:42:34.4125282Z"
      }.
      iKey: redacted.
trce: ServiceProfiler.EventPipe.Client.SampleTransfers.CustomEventsTracker[0]
      [2020-06-12T00:42:59.9263173+00:00] Sending custom event to AI: 
      {
        "RequestId": "e74667273125944c",
        "ServiceProfilerVersion": "v2",
        "ServiceProfilerContent": "v1|eastus-kdhwlf5sz6p6s|e54708db-77b6-457e-b577-103e84229f2c|c5e2cdd6ce11|1|2020-06-12T00:42:16.8870040Z|/#1/1/1/1/|2020-06-12T00:42:20.0284254Z|2020-06-12T00:42:27.1162825Z"
      }.
      iKey: redacted.
dbug: ServiceProfiler.EventPipe.Client.SampleTransfers.CustomEventsTracker[0]
      3 events has been sent to AI as CustomEvents
trce: ServiceProfiler.EventPipe.Client.SampleTransfers.CustomEventsTracker[0]
      [2020-06-12T00:42:59.9300728+00:00] Sending custom event to AI: 
      {
        "FileId": "SOPwRjuLkCnO",
        "DataCube": "e54708db-77b6-457e-b577-103e84229f2c",
        "Source": "OneTimeSchedulingPolicy",
        "ProcessId": "1",
        "OperatingSystem": "Unix 4.19.104.0",
        "StampId": "eastus-kdhwlf5sz6p6s",
        "EtlFileSessionId": "2020-06-12T00:42:16.8870040Z",
        "MachineName": "c5e2cdd6ce11"
      }.
      iKey: redacted.
xiaomi7732 commented 4 years ago

And here's my docker file just FYI:

FROM mcr.microsoft.com/dotnet/core/sdk:3.1-alpine AS build-env
WORKDIR /app

# Copy csproj and restore as distinct layers
COPY *.csproj ./
RUN dotnet restore

# Copy everything else and build
COPY . ./
RUN dotnet publish -c Release -o out

# Build runtime image
FROM mcr.microsoft.com/dotnet/core/aspnet:3.1-alpine
WORKDIR /app
COPY --from=build-env /app/out .
ENTRYPOINT ["dotnet", "ProfilerForAlpine.dll"]
xiaomi7732 commented 4 years ago

@saurabhpati Your repro is in .NET Core 2.2 Ubuntu container, could you please open another issue, turn on the Trace logs? I'll help you troubleshooting there.

xiaomi7732 commented 3 years ago

Close this due to no actionable. Feel free to open new issue if more help is needed.