-
Notifications
You must be signed in to change notification settings - Fork 715
/
Copy pathStartStopActivityComputer.cs
1682 lines (1532 loc) · 81.8 KB
/
StartStopActivityComputer.cs
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
// Copyright (c) Microsoft Corporation. All rights reserved
// This file is best viewed using outline mode (Ctrl-M Ctrl-O)
//
// This program uses code hyperlinks available as part of the HyperAddin Visual Studio plug-in.
// It is available from http://www.codeplex.com/hyperAddin
// using Microsoft.Diagnostics.Tracing.Parsers;
//#define HTTP_SERVICE_EVENTS
using Microsoft.Diagnostics.Tracing.Etlx;
using Microsoft.Diagnostics.Tracing.Parsers;
using Microsoft.Diagnostics.Tracing.Parsers.ApplicationServer;
using Microsoft.Diagnostics.Tracing.Parsers.AspNet;
using Microsoft.Diagnostics.Tracing.Parsers.Clr;
using Microsoft.Diagnostics.Tracing.Session;
using Microsoft.Diagnostics.Tracing.Stacks;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Text;
using StartStopKey = System.Guid; // The start-stop key is unique in the trace. We incorperate the process as well as activity ID to achieve this.
// TODO this leaks if stops are missing.
namespace Microsoft.Diagnostics.Tracing
{
/// <summary>
/// Calculates start-stop activities (computes duration), It uses the 'standard' mechanism of using
/// ActivityIDs to corelate the start and stop (and any other events between the start and stop,
/// and use the RelatedActivityID on START events to indicate the creator of the activity, so you can
/// form nested start-stop activities.
/// </summary>
public unsafe class StartStopActivityComputer
{
/// <summary>
/// Create a new ServerRequest Computer.
/// </summary>
public StartStopActivityComputer(TraceLogEventSource source, ActivityComputer taskComputer, bool ignoreApplicationInsightsRequestsWithRelatedActivityId = true)
{
m_ignoreApplicationInsightsRequestsWithRelatedActivityId = ignoreApplicationInsightsRequestsWithRelatedActivityId;
taskComputer.NoCache = true; // Can't cache start-stops (at the moment)
m_source = source;
m_activeStartStopActivities = new Dictionary<StartStopKey, StartStopActivity>();
m_taskComputer = taskComputer;
// Whenever a new Activity is created, propagate the start-stop activity from the creator
// to the created task.
taskComputer.Create += delegate (TraceActivity activity, TraceEvent data)
{
TraceActivity creator = activity.Creator;
if (creator == null)
{
return;
}
StartStopActivity startStopActivity = m_traceActivityToStartStopActivity.Get((int)creator.Index);
if (startStopActivity == null)
{
return;
}
m_traceActivityToStartStopActivity.Set((int)activity.Index, startStopActivity);
};
// Only need to fix up V4.6 Windows-ASP activity ids. It can be removed after we
// don't care about V4.6 runtimes (since it is fixed in V4.6.2 and beyond).
// It basically remembers the related activity ID of the last RequestSend event on
// each thread, which we use to fix the activity ID of the RequestStart event
KeyValuePair<Guid, Guid>[] threadToLastAspNetGuids = new KeyValuePair<Guid, Guid>[m_source.TraceLog.Threads.Count];
#if HTTP_SERVICE_EVENTS
// Sadly, the Microsoft-Windows-HttpService HTTP_OPCODE_DELIVER event gets logged in
// the kernel, so you don't know what process or thread is going to be get the request
// We hack around this by looking for a nearby ReadyTHread or CSwitch event. These
// variables remember the information needed to transfer these to cswitch in the
// correct process.
// remembers the last deliver event.
string lastHttpServiceDeliverUrl = null;
Guid lastHttpServiceDeliverActivityID = new Guid();
int lastHttpServiceReceiveRequestThreadId = 0;
int lastHttpServiceReceiveRequestTargetProcessId = 0;
Dictionary<long, int> mapConnectionToTargetProcess = new Dictionary<long, int>();
#endif
var dynamicParser = source.Dynamic;
dynamicParser.All += delegate (TraceEvent data)
{
// Special case IIS. It does not use start and stop opcodes (Ugg), but otherwise
// follows normal start-stop activity ID conventions. We also want it to work even
// though it is not a EventSource.
if (data.ID <= (TraceEventID)2 && data.ProviderGuid == MicrosoftWindowsIISProvider)
{
if (data.ID == (TraceEventID)1)
{
// TODO HACK. We have seen IIS Start and stop events that only have a
// context ID and no more. They also seem to be some sort of nested event
// It really looks like a bug that they were emitted. Ignore them.
if (16 < data.EventDataLength)
{
string extraStartInfo = data.PayloadByName("RequestURL") as string;
OnStart(data, extraStartInfo, null, null, null, "IISRequest");
}
}
else if (data.ID == (TraceEventID)2)
{
// TODO HACK. We have seen IIS Start and stop events that only have a
// context ID and no more. They also seem to be some sort of nested event
// It really looks like a bug that they were emitted. Ignore them.
if (16 < data.EventDataLength)
{
OnStop(data);
}
}
}
#if HTTP_SERVICE_EVENTS
else if (data.Task == (TraceEventTask)1 && data.ProviderGuid == MicrosoftWindowsHttpService)
{
if (data.ID == (TraceEventID)1) // HTTP_TASK_REQUEST / HTTP_OPCODE_RECEIVE_REQUEST
{
Debug.Assert(data.EventName == "HTTP_TASK_REQUEST/HTTP_OPCODE_RECEIVE_REQUEST");
lastHttpServiceReceiveRequestTargetProcessId = 0;
lastHttpServiceReceiveRequestThreadId = data.ThreadID;
object connectionID = data.PayloadByName("ConnectionId");
if (connectionID != null && connectionID is long)
mapConnectionToTargetProcess.TryGetValue((long)connectionID, out lastHttpServiceReceiveRequestTargetProcessId);
}
else if (data.ID == (TraceEventID)3) // HTTP_TASK_REQUEST/HTTP_OPCODE_DELIVER
{
Debug.Assert(data.EventName == "HTTP_TASK_REQUEST/HTTP_OPCODE_DELIVER");
if (lastHttpServiceReceiveRequestThreadId == data.ThreadID && lastHttpServiceReceiveRequestTargetProcessId != 0)
{
lastHttpServiceDeliverUrl = data.PayloadByName("Url") as string;
lastHttpServiceDeliverActivityID = data.ActivityID;
}
else
{
lastHttpServiceDeliverUrl = null;
lastHttpServiceReceiveRequestTargetProcessId = 0;
}
lastHttpServiceReceiveRequestThreadId = 0;
}
else if (data.ID == (TraceEventID)12 || data.ID == (TraceEventID)8) // HTTP_TASK_REQUEST/HTTP_OPCODE_FAST_SEND HTTP_TASK_REQUEST/HTTP_OPCODE_FAST_RESPONSE
{
if (data.ID == (TraceEventID)8)
{
object connectionID = data.PayloadByName("ConnectionId");
if (connectionID != null && connectionID is long)
mapConnectionToTargetProcess[(long)connectionID] = data.ProcessID;
}
Debug.Assert(data.ID != (TraceEventID)12 || data.EventName == "HTTP_TASK_REQUEST/HTTP_OPCODE_FAST_SEND");
Debug.Assert(data.ID != (TraceEventID)8 || data.EventName == "HTTP_TASK_REQUEST/HTTP_OPCODE_FAST_RESPONSE");
OnStop(data);
}
}
#endif
// TODO decide what the correct heuristic for deciding what start-stop events are interesting.
// Currently I only do this for things that might be an EventSource
if (!TraceEventProviders.MaybeAnEventSource(data.ProviderGuid))
{
return;
}
// Try to filter out things quickly. We really only care about start and stop events
// (except in special cases where the conventions were not followed and we fix them up).
if (data.Opcode != TraceEventOpcode.Start && data.Opcode != TraceEventOpcode.Stop)
{
// In V4.6 the activity ID for Microsoft-Windows-ASPNET/Request/Start is improperly set, but we can fix it by
// looking at the 'send' event that happens just before it. Can be removed when V4.6 no longer deployed.
// TODO remove (including threadToLastAspNetGuid) after 9/2016
if (data.Opcode == (TraceEventOpcode)9 && data.ProviderGuid == MicrosoftWindowsASPNetProvider)
{
TraceThread thread = data.Thread();
if (thread != null)
{
threadToLastAspNetGuids[(int)thread.ThreadIndex] = new KeyValuePair<Guid, Guid>(data.ActivityID, data.RelatedActivityID);
}
}
// These providers are weird in that they don't event do start and stop opcodes. This is unfortunate.
else if (data.Opcode == TraceEventOpcode.Info && data.ProviderGuid == AdoNetProvider)
{
FixAndProcessAdoNetEvents(data);
}
// Special case - OpenTelemetry-Sdk
else if (data.Opcode == TraceEventOpcode.Info && data.providerGuid == OpenTelemetrySdkProvider)
{
FixAndProcessOpenTelemetrySdkEvents(data);
}
return;
}
// OK so now we only have EventSources with start and stop opcodes.
// There are a few that don't follow conventions completely, and then we handle the 'normal' case
if (data.ProviderGuid == MicrosoftApplicationInsightsDataProvider)
{
FixAndProcessAppInsightsEvents(data);
}
else if (data.ProviderGuid == FrameworkEventSourceTraceEventParser.ProviderGuid)
{
FixAndProcessFrameworkEvents(data);
}
else if (data.ProviderGuid == MicrosoftWindowsASPNetProvider)
{
FixAndProcessWindowsASP(data, threadToLastAspNetGuids);
}
else if (data.ProviderGuid == MicrosoftDiagnosticsActivityTrackingProvider)
{
ProcessActivityTrackingProviderEvents(data);
}
else // Normal case EventSource Start-Stop events that follow proper conventions.
{
// We currently only handle Start-Stops that use the ActivityPath convention
// We could change this, but it is not clear what value it has to do that.
Guid activityID = data.ActivityID;
if (StartStopActivityComputer.IsActivityPath(activityID, data.ProcessID))
{
if (data.Opcode == TraceEventOpcode.Start)
{
if (data.ProviderGuid == MicrosoftDiagnosticsDiagnosticSourceProvider)
{
// Inside the function, it will filter the events by 'EventName'.
// It will only process "Microsoft.EntityFrameworkCore.BeforeExecuteCommand" and "Microsoft.AspNetCore.Hosting.BeginRequest".
if (TryProcessDiagnosticSourceStartEvents(data))
{
return;
}
}
string extraStartInfo = null;
// Include the first argument in extraInfo if it is a string (e.g. a URL or other identifier).
if (0 < data.PayloadNames.Length)
{
try { extraStartInfo = data.PayloadValue(0) as string; }
catch (Exception) { }
if (extraStartInfo != null)
{
extraStartInfo = "/" + data.payloadNames[0] + "=" + extraStartInfo;
}
}
OnStart(data, extraStartInfo);
}
else
{
Debug.Assert(data.Opcode == TraceEventOpcode.Stop);
OnStop(data);
}
}
else
{
Trace.WriteLine("Skipping start at " + data.TimeStampRelativeMSec.ToString("n3") + " name = " + data.EventName);
}
}
};
#if HTTP_SERVICE_EVENTS
#if TODO_FIX_NOW // FIX NOW Use or remove.
// We monitor ReadyThread to make HttpService events more useful (see nodes above on lastHttpServiceUrl)
m_source.Kernel.DispatcherReadyThread += delegate (DispatcherReadyThreadTraceData data)
{
if (lastHttpServiceUrl == null)
return;
};
#endif
m_source.Kernel.ThreadCSwitch += delegate (CSwitchTraceData data)
{
// This code is to transfer information from the Microsoft-Windows-HttpService HTTP_TASK_REQUEST/HTTP_OPCODE_DELIVER
// event (that happens in the System process, not the target, and move it to the context switch that wakes up
// in order to service the event.
if (lastHttpServiceDeliverUrl == null)
return;
if (data.ProcessID != lastHttpServiceReceiveRequestTargetProcessId)
return;
// Test Stack
Guid activityID = lastHttpServiceDeliverActivityID;
OnStart(data, "url=" + lastHttpServiceDeliverUrl, &activityID, null, null, "HttpServiceRec");
lastHttpServiceDeliverUrl = null;
lastHttpServiceDeliverActivityID = Guid.Empty;
};
#endif
// Show the exception handling call stacks as a separate Activity.
// This can help users notice the time spent in the exception handling logic.
var clrExceptionParser = m_source.Clr;
clrExceptionParser.ExceptionCatchStart += delegate (ExceptionHandlingTraceData data)
{
OnStart(data, data.MethodName, null, null, null, "ExceptionHandling");
};
clrExceptionParser.ExceptionCatchStop += delegate (EmptyTraceData data)
{
OnStop(data);
};
var aspNetParser = new AspNetTraceEventParser(m_source);
aspNetParser.AspNetReqStart += delegate (AspNetStartTraceData data)
{
// if the related activity is not present, try using the context ID as the creator ID to look up.
// The ASPNet events reuse the IIS ID which means first stop kills both. As it turns out
// IIS stops before ASP (also incorrect) but it mostly this is benign...
StartStopActivity creator = null;
if (data.RelatedActivityID == Guid.Empty)
{
creator = GetActiveStartStopActivityTable(data.ContextId, data.ProcessID);
}
Guid activityId = data.ContextId;
OnStart(data, data.Path, &activityId, null, creator, null, false);
};
aspNetParser.AspNetReqStop += delegate (AspNetStopTraceData data)
{
Guid activityId = data.ContextId;
OnStop(data, &activityId);
};
// There are other ASP.NET events that have context information and this is useful
aspNetParser.AspNetReqStartHandler += delegate (AspNetStartHandlerTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPipelineModuleEnter += delegate (AspNetPipelineModuleEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqGetAppDomainEnter += delegate (AspNetGetAppDomainEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
// These are probably not important, but they may help.
aspNetParser.AspNetReqRoleManagerBegin += delegate (AspNetRoleManagerBeginTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqRoleManagerGetUserRoles += delegate (AspNetRoleManagerGetUserRolesTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqRoleManagerEnd += delegate (AspNetRoleManagerEndTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqMapHandlerEnter += delegate (AspNetMapHandlerEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqMapHandlerLeave += delegate (AspNetMapHandlerLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqHttpHandlerEnter += delegate (AspNetHttpHandlerEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqHttpHandlerLeave += delegate (AspNetHttpHandlerLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPagePreInitEnter += delegate (AspNetPagePreInitEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPagePreInitLeave += delegate (AspNetPagePreInitLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageInitEnter += delegate (AspNetPageInitEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageInitLeave += delegate (AspNetPageInitLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageLoadEnter += delegate (AspNetPageLoadEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageLoadLeave += delegate (AspNetPageLoadLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPagePreRenderEnter += delegate (AspNetPagePreRenderEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPagePreRenderLeave += delegate (AspNetPagePreRenderLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageSaveViewstateEnter += delegate (AspNetPageSaveViewstateEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageSaveViewstateLeave += delegate (AspNetPageSaveViewstateLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageRenderEnter += delegate (AspNetPageRenderEnterTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
aspNetParser.AspNetReqPageRenderLeave += delegate (AspNetPageRenderLeaveTraceData data)
{
SetThreadToStartStopActivity(data, data.ContextId);
};
var WCFParser = new ApplicationServerTraceEventParser(m_source);
WCFParser.WebHostRequestStart += delegate (Multidata69TemplateATraceData data)
{
OnStart(data, data.VirtualPath);
};
WCFParser.WebHostRequestStop += delegate (OneStringsTemplateATraceData data)
{
OnStop(data);
};
// Microsoft-Windows-Application Server-Applications/TransportReceive/Stop
WCFParser.MessageReceivedByTransport += delegate (Multidata29TemplateHATraceData data)
{
// This actually looks like a Stop opcode, but it is really a start because
// it has a RelatedActivityID
OnStart(data, data.ListenAddress, null, null, null, "OperationDispatch");
};
// These Stop the Starts. We don't want leaks in the common case.
WCFParser.DispatchFailed += delegate (Multidata38TemplateHATraceData data)
{
OnStop(data);
};
WCFParser.DispatchSuccessful += delegate (Multidata38TemplateHATraceData data)
{
OnStop(data);
};
WCFParser.OperationInvoked += delegate (Multidata24TemplateHATraceData data)
{
// The creator uses the same ID as myself.
OnStart(data, data.MethodName, null, null, GetActiveStartStopActivityTable(data.ActivityID, data.ProcessID));
};
WCFParser.OperationCompleted += delegate (Multidata28TemplateHATraceData data)
{
OnStop(data);
};
WCFParser.ServiceActivationStart += SetThreadToStartStopActivity;
WCFParser.ServiceHostFactoryCreationStart += SetThreadToStartStopActivity;
WCFParser.ServiceHostStarted += SetThreadToStartStopActivity;
WCFParser.HttpMessageReceiveStart += SetThreadToStartStopActivity;
WCFParser.HttpContextBeforeProcessAuthentication += SetThreadToStartStopActivity;
WCFParser.TokenValidationStarted += SetThreadToStartStopActivity;
WCFParser.MessageReadByEncoder += SetThreadToStartStopActivity;
WCFParser.HttpResponseReceiveStart += SetThreadToStartStopActivity;
WCFParser.SocketReadStop += SetThreadToStartStopActivity;
WCFParser.SocketAsyncReadStop += SetThreadToStartStopActivity;
WCFParser.SignatureVerificationStart += SetThreadToStartStopActivity;
WCFParser.SignatureVerificationSuccess += SetThreadToStartStopActivity;
WCFParser.ChannelReceiveStop += SetThreadToStartStopActivity;
WCFParser.DispatchMessageStart += SetThreadToStartStopActivity;
WCFParser.IncrementBusyCount += SetThreadToStartStopActivity;
WCFParser.DispatchMessageBeforeAuthorization += SetThreadToStartStopActivity;
WCFParser.ActionItemScheduled += SetThreadToStartStopActivity;
WCFParser.GetServiceInstanceStart += SetThreadToStartStopActivity;
WCFParser.GetServiceInstanceStop += SetThreadToStartStopActivity;
WCFParser.ActionItemCallbackInvoked += SetThreadToStartStopActivity;
WCFParser.ChannelReceiveStart += SetThreadToStartStopActivity;
WCFParser.OutgoingMessageSecured += SetThreadToStartStopActivity;
WCFParser.SocketWriteStart += SetThreadToStartStopActivity;
WCFParser.SocketAsyncWriteStart += SetThreadToStartStopActivity;
WCFParser.BinaryMessageEncodingStart += SetThreadToStartStopActivity;
WCFParser.MtomMessageEncodingStart += SetThreadToStartStopActivity;
WCFParser.TextMessageEncodingStart += SetThreadToStartStopActivity;
WCFParser.BinaryMessageDecodingStart += SetThreadToStartStopActivity;
WCFParser.MtomMessageDecodingStart += SetThreadToStartStopActivity;
WCFParser.TextMessageDecodingStart += SetThreadToStartStopActivity;
WCFParser.StreamedMessageWrittenByEncoder += SetThreadToStartStopActivity;
WCFParser.MessageWrittenAsynchronouslyByEncoder += SetThreadToStartStopActivity;
WCFParser.BufferedAsyncWriteStop += SetThreadToStartStopActivity;
WCFParser.HttpPipelineProcessResponseStop += SetThreadToStartStopActivity;
WCFParser.WebSocketAsyncWriteStop += SetThreadToStartStopActivity;
WCFParser.MessageSentByTransport += SetThreadToStartStopActivity;
WCFParser.HttpSendStop += SetThreadToStartStopActivity;
WCFParser.DispatchMessageStop += SetThreadToStartStopActivity;
WCFParser.DispatchSuccessful += SetThreadToStartStopActivity;
// Server-side quota information.
WCFParser.MaxReceivedMessageSizeExceeded += SetThreadToStartStopActivity;
WCFParser.MaxPendingConnectionsExceeded += SetThreadToStartStopActivity;
WCFParser.ReaderQuotaExceeded += SetThreadToStartStopActivity;
WCFParser.NegotiateTokenAuthenticatorStateCacheExceeded += SetThreadToStartStopActivity;
WCFParser.NegotiateTokenAuthenticatorStateCacheRatio += SetThreadToStartStopActivity;
WCFParser.SecuritySessionRatio += SetThreadToStartStopActivity;
WCFParser.PendingConnectionsRatio += SetThreadToStartStopActivity;
WCFParser.ConcurrentCallsRatio += SetThreadToStartStopActivity;
WCFParser.ConcurrentSessionsRatio += SetThreadToStartStopActivity;
WCFParser.ConcurrentInstancesRatio += SetThreadToStartStopActivity;
WCFParser.PendingAcceptsAtZero += SetThreadToStartStopActivity;
// WCF client operations.
// TODO FIX NOW, I have never run these! Get some data to test against.
WCFParser.ClientOperationPrepared += delegate (Multidata22TemplateHATraceData data)
{
string extraInformation = "/Action=" + data.ServiceAction + "/URL=" + data.Destination;
OnStart(data, extraInformation, null, null, GetActiveStartStopActivityTable(data.ActivityID, data.ProcessID), "ClientOperation");
};
WCFParser.ServiceChannelCallStop += delegate (Multidata22TemplateHATraceData data)
{
OnStop(data);
};
}
/// <summary>
/// The current start-stop activity on the given thread.
/// If present 'context' is used to look up the current activityID and try to use that to repair missing Starts.
/// Basically if we can't figure out what StartStop activity the thread from just the threadID we can use the activityID
/// from the 'context' event to find it as a backup.
/// </summary>
public StartStopActivity GetCurrentStartStopActivity(TraceThread thread, TraceEvent context = null)
{
DoStopIfNecessary(); // Do any deferred stops.
// Search up the stack of tasks, seeing if we have a start-stop activity.
TraceActivity curTaskActivity = m_taskComputer.GetCurrentActivity(thread);
if (curTaskActivity == null)
{
return null;
}
int taskIndex = (int)curTaskActivity.Index;
StartStopActivity ret = m_traceActivityToStartStopActivity.Get(taskIndex);
if (ret == null && context != null)
{
if (context.ActivityID != Guid.Empty)
{
ret = GetActiveStartStopActivityTable(context.ActivityID, context.ProcessID);
}
}
// If the activity is stopped, then don't return it, return its parent.
while (ret != null)
{
if (!ret.IsStopped)
{
return ret;
}
ret = ret.Creator;
}
return ret;
}
/// <summary>
/// Gets the current Start-Stop activity for a given TraceActivity.
/// </summary>
/// <param name="curActivity"></param>
/// <returns></returns>
public StartStopActivity GetStartStopActivityForActivity(TraceActivity curActivity)
{
int taskIndex = (int)curActivity.Index;
StartStopActivity ret = m_traceActivityToStartStopActivity.Get(taskIndex);
// If the activity is stopped, then don't return it, return its parent.
while (ret != null)
{
if (!ret.IsStopped)
{
return ret;
}
ret = ret.Creator;
}
return ret;
}
/// <summary>
/// Returns a stack index representing the nesting of Start-Stop activities for the thread 'curThread' at the current time
/// (At this point of the current event for the computer). The stack starts with a frame for the process of the thread, then
/// has all the start-stop activity frames, then a frame representing 'topThread' which may not be the same as 'thread' since
/// 'topThread' is the thread that spawned the first task, not the currently executing thread.
///
/// Normally this stack is for the current time, but if 'getAtCreationTime' is true, it will compute the
/// stack at the time that the current activity was CREATED rather than the current time. This works
/// better for await time
/// </summary>
public StackSourceCallStackIndex GetCurrentStartStopActivityStack(MutableTraceEventStackSource outputStackSource, TraceThread curThread, TraceThread topThread, bool getAtCreationTime = false)
{
StartStopActivity startStop = null;
// Best effort to get the activity as it exists at creation time of the current activity (AWAIT).
if (getAtCreationTime)
{
TraceActivity curTaskActivity = m_taskComputer.GetCurrentActivity(curThread);
if (curTaskActivity != null)
{
startStop = m_traceActivityToStartStopActivity.Get((int)curTaskActivity.Index);
if (startStop != null)
{
// Check to make sure that the start-stop stopped AFTER the activity was created.
if (startStop.IsStopped && startStop.StartTimeRelativeMSec + startStop.DurationMSec < curTaskActivity.CreationTimeRelativeMSec)
{
startStop = null;
}
}
}
}
if (startStop == null)
{
startStop = GetCurrentStartStopActivity(curThread);
}
// Get the process, and activity frames.
StackSourceCallStackIndex stackIdx = GetStartStopActivityStack(outputStackSource, startStop, topThread.Process);
// Add "Threads pesudo-node"
stackIdx = outputStackSource.Interner.CallStackIntern(outputStackSource.Interner.FrameIntern("Threads"), stackIdx);
// Add the thread.
stackIdx = outputStackSource.Interner.CallStackIntern(outputStackSource.Interner.FrameIntern(topThread.VerboseThreadName), stackIdx);
return stackIdx;
}
/// <summary>
/// Gets a stack that represents the nesting of the Start-Stop tasks. curActivity can be null, in which case just he process node is returned.
/// </summary>
public StackSourceCallStackIndex GetStartStopActivityStack(MutableTraceEventStackSource outputStackSource, StartStopActivity curActivity, TraceProcess process)
{
StackSourceCallStackIndex stackIdx = outputStackSource.GetCallStackForProcess(process);
// Add Pseudo frame for whether it is an activity or not
string firstFrameName = curActivity == null ? "(Non-Activities)" : "(Activities)";
stackIdx = outputStackSource.Interner.CallStackIntern(outputStackSource.Interner.FrameIntern(firstFrameName), stackIdx);
if (curActivity != null)
{
stackIdx = curActivity.GetActivityStack(outputStackSource, stackIdx);
}
return stackIdx;
}
// Events
/// <summary>
/// If set, called AFTER a Start-Stop activity starts, called with the activity and the event that caused the start.
/// </summary>
public Action<StartStopActivity, TraceEvent> Start;
/// <summary>
/// If set, called BEFORE a Start-Stop activity stops, called with the activity and the event that caused the start.
/// </summary>
public Action<StartStopActivity, TraceEvent> Stop;
// TODO decide if we need this...
// public Action<StartStopActivity> AfterStop;
/// <summary>
/// Returns true if 'guid' follow the EventSouce style activity ID for the process with ID processID.
/// You can pass a process ID of 0 to this routine and it will do the best it can, but the possibility
/// of error is significantly higher (but still under .1%)
/// </summary>
public static unsafe bool IsActivityPath(Guid guid, int processID)
{
uint* uintPtr = (uint*)&guid;
uint sum = uintPtr[0] + uintPtr[1] + uintPtr[2] + 0x599D99AD;
if (processID == 0)
{
// We guess that the process ID is < 20 bits and because it was xored
// with the lower bits, the upper 12 bits should be independent of the
// particular process, so we can at least confirm that the upper bits
// match.
return ((sum & 0xFFF00000) == (uintPtr[3] & 0xFFF00000));
}
if ((sum ^ (uint)processID) == uintPtr[3]) // This is the new style
{
return true;
}
return (sum == uintPtr[3]); // THis is old style where we don't make the ID unique machine wide.
}
/// <summary>
/// Assuming guid is an Activity Path, extract the process ID from it.
/// </summary>
public static unsafe int ActivityPathProcessID(Guid guid)
{
uint* uintPtr = (uint*)&guid;
uint sum = uintPtr[0] + uintPtr[1] + uintPtr[2] + 0x599D99AD;
return (int)(sum ^ uintPtr[3]);
}
/// <summary>
/// returns a string representation for the activity path. If the GUID is not an activity path then it returns
/// the normal string representation for a GUID.
/// </summary>
/// <remarks>
/// 0001111d-0000-0000-0000-00007bc7be59 will pass IsActivityPath check only when process Id 2125233 is provided.
/// </remarks>
public static unsafe string ActivityPathString(Guid guid, int processId = 0)
{
return IsActivityPath(guid, processId) ? CreateActivityPathString(guid) : guid.ToString();
}
internal static unsafe string CreateActivityPathString(Guid guid)
{
var processID = ActivityPathProcessID(guid);
StringBuilder sb = Utilities.StringBuilderCache.Acquire();
if (processID != 0)
{
sb.Append("/#"); // Use /# to mark the fact that the first number is a process ID.
sb.Append(processID);
}
else
{
sb.Append('/'); // Use // to start to make it easy to anchor
}
byte* bytePtr = (byte*)&guid;
byte* endPtr = bytePtr + 12;
char separator = '/';
while (bytePtr < endPtr)
{
uint nibble = (uint)(*bytePtr >> 4);
bool secondNibble = false; // are we reading the second nibble (low order bits) of the byte.
NextNibble:
if (nibble == (uint)NumberListCodes.End)
{
break;
}
if (nibble <= (uint)NumberListCodes.LastImmediateValue)
{
sb.Append('/').Append(nibble);
if (!secondNibble)
{
nibble = (uint)(*bytePtr & 0xF);
secondNibble = true;
goto NextNibble;
}
// We read the second nibble so we move on to the next byte.
bytePtr++;
continue;
}
else if (nibble == (uint)NumberListCodes.PrefixCode)
{
// This are the prefix codes. If the next nibble is MultiByte, then this is an overflow ID.
// we we denote with a $ instead of a / separator.
// Read the next nibble.
if (!secondNibble)
{
nibble = (uint)(*bytePtr & 0xF);
}
else
{
bytePtr++;
if (endPtr <= bytePtr)
{
break;
}
nibble = (uint)(*bytePtr >> 4);
}
if (nibble < (uint)NumberListCodes.MultiByte1)
{
// If the nibble is less than MultiByte we have not defined what that means
// For now we simply give up, and stop parsing. We could add more cases here...
return guid.ToString();
}
// If we get here we have a overflow ID, which is just like a normal ID but the separator is $
separator = '$';
// Fall into the Multi-byte decode case.
}
Debug.Assert((uint)NumberListCodes.MultiByte1 <= nibble);
// At this point we are decoding a multi-byte number, either a normal number or a
// At this point we are byte oriented, we are fetching the number as a stream of bytes.
uint numBytes = nibble - (uint)NumberListCodes.MultiByte1;
uint value = 0;
if (!secondNibble)
{
value = (uint)(*bytePtr & 0xF);
}
bytePtr++; // Advance to the value bytes
numBytes++; // Now numBytes is 1-4 and represents the number of bytes to read.
if (endPtr < bytePtr + numBytes)
{
break;
}
// Compute the number (little endian) (thus backwards).
for (int i = (int)numBytes - 1; 0 <= i; --i)
{
value = (value << 8) + bytePtr[i];
}
// Print the value
sb.Append(separator).Append(value);
bytePtr += numBytes; // Advance past the bytes.
}
sb.Append('/');
return Utilities.StringBuilderCache.GetStringAndRelease(sb);
}
#region private
private static readonly Guid MicrosoftWindowsASPNetProvider = new Guid("ee799f41-cfa5-550b-bf2c-344747c1c668");
private static readonly Guid MicrosoftWindowsIISProvider = new Guid("de4649c9-15e8-4fea-9d85-1cdda520c334");
private static readonly Guid AdoNetProvider = new Guid("6a4dfe53-eb50-5332-8473-7b7e10a94fd1");
private static readonly Guid MicrosoftWindowsHttpService = new Guid("dd5ef90a-6398-47a4-ad34-4dcecdef795f");
private static readonly Guid MicrosoftDiagnosticsDiagnosticSourceProvider = new Guid("ADB401E1-5296-51F8-C125-5FDA75826144");
private static readonly Guid OpenTelemetrySdkProvider = new Guid("af2d5796-946b-50cb-5f76-166a609afcbb");
// EventSourceName: Microsoft-ApplicationInsights-Data
// Reference for definition: https://raw.githubusercontent.com/Microsoft/ApplicationInsights-dotnet/e8f047f6e48abae0e88a9c77bf65df858c442940/src/Microsoft.ApplicationInsights/Extensibility/Implementation/RichPayloadEventSource.cs
private static readonly Guid MicrosoftApplicationInsightsDataProvider = new Guid("a62adddb-6b4b-519d-7ba1-f983d81623e0");
// A generic EventSource ("Microsoft-Diagnostics-ActivityTracking") for marking the start and stop of an activity.
// Used by non-.NET platforms such as Java
private static readonly Guid MicrosoftDiagnosticsActivityTrackingProvider = new Guid("3b268b3d-903f-5835-c77e-790d518a26c4");
// The main start and stop logic.
private unsafe StartStopActivity OnStart(TraceEvent data, string extraStartInfo = null, Guid* activityId = null, TraceThread thread = null, StartStopActivity creator = null, string taskName = null, bool useCurrentActivityForCreatorAsFallback = true)
{
// Because we want the stop to logically be 'after' the actual stop event (so that the stop looks like
// it is part of the start-stop activity we defer it until the next event. If there is already
// a deferral, we can certainly do that one now.
DoStopIfNecessary();
if (thread == null)
{
thread = data.Thread();
if (thread == null)
{
return null;
}
}
TraceActivity curTaskActivity = m_taskComputer.GetCurrentActivity(thread);
ActivityIndex taskIndex = curTaskActivity.Index;
if (creator == null)
{
if (data.RelatedActivityID != Guid.Empty)
{
creator = GetActiveStartStopActivityTable(data.RelatedActivityID, data.ProcessID);
if (creator == null)
{
Trace.WriteLine(data.TimeStampRelativeMSec.ToString("n3") + " Warning: Could not find creator Activity " + StartStopActivityComputer.ActivityPathString(data.RelatedActivityID));
}
}
// If there is no RelatedActivityID, or the activity ID we have is 'bad' (dead), fall back to the activity we track.
if (creator == null && useCurrentActivityForCreatorAsFallback)
{
creator = GetStartStopActivityForActivity(curTaskActivity);
}
}
if (taskName == null)
{
taskName = data.TaskName;
}
// Create the new activity.
StartStopActivity activity;
if (activityId != null)
{
activity = new StartStopActivity(data, taskName, ref *activityId, creator, m_nextIndex++, extraStartInfo);
}
else
{
Guid activityIdValue = data.ActivityID;
activity = new StartStopActivity(data, taskName, ref activityIdValue, creator, m_nextIndex++, extraStartInfo);
}
SetActiveStartStopActivityTable(activity.ActivityID, data.ProcessID, activity); // Put it in our table of live activities.
m_traceActivityToStartStopActivity.Set((int)taskIndex, activity);
// Issue callback if requested AFTER state update
var onStartAfter = Start;
if (onStartAfter != null)
{
onStartAfter(activity, data);
}
return activity;
}
private void SetThreadToStartStopActivity(TraceEvent data)
{
SetThreadToStartStopActivity(data, data.ActivityID);
}
private void SetThreadToStartStopActivity(TraceEvent data, Guid activityId)
{
StartStopActivity startStopActivity = GetActiveStartStopActivityTable(activityId, data.ProcessID);
if (startStopActivity != null)
{
// Because we want the stop to logically be 'after' the actual stop event (so that the stop looks like
// it is part of the start-stop activity we defer it until the next event. If there is already
// a deferral, we can certainly do that one now.
DoStopIfNecessary();
TraceThread thread = data.Thread();
if (thread == null)
{
return;
}
TraceActivity curTaskActivity = m_taskComputer.GetCurrentActivity(thread);
ActivityIndex taskIndex = curTaskActivity.Index;
StartStopActivity previousStartStopActivity = m_traceActivityToStartStopActivity.Get((int)taskIndex);
if (previousStartStopActivity == null)
{
m_traceActivityToStartStopActivity.Set((int)taskIndex, startStopActivity);
}
else if (previousStartStopActivity != startStopActivity)
{
Trace.WriteLine("Warning: Thread " + data.ThreadID + " at " + data.TimeStampRelativeMSec.ToString("n3") +
" wants to overwrite activity started at " + previousStartStopActivity.StartTimeRelativeMSec.ToString("n3"));
}
}
}
private unsafe void OnStop(TraceEvent data, Guid* activityID = null)
{
// Because we want the stop to logically be 'after' the actual stop event (so that the stop looks like
// it is part of the start-stop activity we defer it until the next event. If there is already
// a deferral, we can certainly do that one now.
DoStopIfNecessary();
TraceThread thread = data.Thread();
if (thread == null)
{
return;
}
TraceActivity curTaskActivity = m_taskComputer.GetCurrentActivity(thread);
ActivityIndex taskIndex = curTaskActivity.Index;
StartStopActivity activity;
if (activityID != null)
{
activity = GetActiveStartStopActivityTable(*activityID, data.ProcessID);
}
else
{
activity = GetActiveStartStopActivityTable(data.ActivityID, data.ProcessID);
}
if (activity != null)
{
// We defer the stop until the NEXT event (so that stops look like they are IN the activity).
// So here we just capture what is needed to do this later (basically on the next event).
activity.RememberStop(data.EventIndex, data.TimeStampRelativeMSec, taskIndex);
m_deferredStop = activity; // Remember this one for deferral.
// Issue callback if requested, this is before state update since we have deferred the stop.
var stop = Stop;
if (stop != null)
{
stop(activity, data);
if (activity.Creator != null && activity.Creator.killIfChildDies && !activity.Creator.IsStopped)
{
stop(activity.Creator, data);
}
}
}
else
{
// TODO GetResponseStream Stops can sometime occur before the start (if they can be accomplished without I/O).
if (!(data.ProviderGuid == FrameworkEventSourceTraceEventParser.ProviderGuid))
{
Guid activityIdValue = activityID != null ? *activityID : data.ActivityID;
Trace.WriteLine("Warning: Unmatched stop at " + data.TimeStampRelativeMSec.ToString("n3") + " ID = " + activityIdValue);
}
}
}
/// <summary>
/// We don't do a stop all processing associated with the stop event is done. Thus if we are not 'on'
/// the stop event, then you can do any deferred processing.
/// </summary>
private void DoStopIfNecessary()
{
// If we are not exactly on the StopEvent then do the deferred stop before doing any processing.
if (m_deferredStop != null && m_deferredStop.StopEventIndex != m_source.CurrentEventIndex)
{
var startStopActivity = m_deferredStop;
var creator = startStopActivity.Creator;
while (creator != null && creator.IsStopped)
{
creator = creator.Creator;
}
m_traceActivityToStartStopActivity.Set((int)startStopActivity.activityIndex, creator);
// If the creator shares the same activity ID, then set the activity ID to the creator, This happens
// when mulitple activities share the same activity ID (not the best practice but reasonably common).
// If this sharing is not present, we can remove the activity ID from the table.
if (creator != null && creator.ActivityID == startStopActivity.ActivityID && creator.ProcessID == startStopActivity.ProcessID)