1// Licensed to the .NET Foundation under one or more agreements.
2// The .NET Foundation licenses this file to you under the MIT license.
3// See the LICENSE file in the project root for more information.
4
5/*****************************************************************************/
6// <OWNER>clrjit</OWNER>
7//
8// This class abstracts the telemetry information collected for the JIT.
9//
10// Goals:
11// 1. Telemetry information should be a NO-op when JIT level telemetry is disabled.
12// 2. Data collection should be actionable.
13// 3. Data collection should comply to privacy rules.
14// 4. Data collection cannot impact JIT/OS performance.
15// 5. Data collection volume should be manageable by our remote services.
16//
17// DESIGN CONCERNS:
18//
19// > To collect data, we use the TraceLogging API provided by Windows.
20//
21// The brief workflow suggested is:
22// #include <TraceLoggingProvider.h>
23// TRACELOGGING_DEFINE_PROVIDER( // defines g_hProvider
24// g_hProvider, // Name of the provider variable
25// "MyProvider", // Human-readable name of the provider
26// (0xb3864c38, 0x4273, 0x58c5, 0x54, 0x5b, 0x8b, 0x36, 0x08, 0x34, 0x34, 0x71)); // Provider GUID
27// int main(int argc, char* argv[]) // or DriverEntry for kernel-mode.
28// {
29// TraceLoggingRegister(g_hProvider, NULL, NULL, NULL); // NULLs only needed for C. Please do not include the
30// // NULLs in C++ code.
31// TraceLoggingWrite(g_hProvider,
32// "MyEvent1",
33// TraceLoggingString(argv[0], "arg0"),
34// TraceLoggingInt32(argc));
35// TraceLoggingUnregister(g_hProvider);
36// return 0;
37// }
38//
39// In summary, this involves:
40// 1. Creating a binary/DLL local provider using:
41// TRACELOGGING_DEFINE_PROVIDER(g_hProvider, "ProviderName", providerId, [option])
42// 2. Registering the provider instance
43// TraceLoggingRegister(g_hProvider)
44// 3. Perform TraceLoggingWrite operations to write out data.
45// 4. Unregister the provider instance.
46// TraceLoggingUnregister(g_hProvider)
47//
48// A. Determining where to create the provider instance?
49// 1) We use the same provider name/GUID as the CLR and the CLR creates its own DLL local provider handle.
50// For CLRJIT.dll, the question is, can the same provider name/GUIDs be shared across binaries?
51//
52// Answer:
53// "For TraceLogging providers, it is okay to use the same provider GUID / name
54// in different binaries. Do not share the same provider handle across DLLs.
55// As long as you do not pass an hProvider from one DLL to another, TraceLogging
56// will properly keep track of the events."
57//
58// 2) CoreCLR is linked into the CLR. CLR already creates an instance, so where do we create the JIT's instance?
59// Answer:
60// "Ideally you would have one provider per DLL, but if you're folding distinct sets
61// of functionality into one DLL (like shell32.dll or similar sort of catch-all things)
62// you can have perhaps a few more providers per binary."
63//
64// B. Determining where to register and unregister the provider instance?
65// 1) For CLRJIT.dll we can register the provider instance during jitDllOnProcessAttach.
66// Since one of our goals is to turn telemetry off, we need to be careful about
67// referencing environment variables during the DLL load and unload path.
68// Referencing environment variables through ConfigDWORD uses UtilCode.
69// This roughly translates to InitUtilcode() being called before jitDllOnProcessAttach.
70//
71// For CLRJIT.dll, compStartup is called on jitOnDllProcessAttach().
72// This can be called twice through sxsJitStartup -- so prevent double initialization.
73// UtilCode is init-ed by this time. The same is true for CoreCLR.
74//
75// 2) For CLRJIT.dll and CoreCLR, compShutdown will be called during jitOnDllProcessDetach().
76//
77// C. Determining the data to collect:
78//
79// IMPORTANT: Since telemetry data can be collected at any time after DLL load,
80// make sure you initialize the compiler state variables you access in telemetry
81// data collection. For example, if you are transmitting method names, then
82// make sure info.compMethodHnd is initialized at that point.
83//
84// 1) Tracking noway assert count:
85// After a noway assert is hit, in both min-opts and non-min-opts, we collect
86// info such as the JIT version, method hash being compiled, filename and
87// line number etc.
88//
89// 2) Tracking baseline for the noway asserts:
90// During DLL unload, we report the number of methods that were compiled by
91// the JIT per process both under normal mode and during min-opts. NOTE that
92// this is ON for all processes.
93//
94// 3) For the future, be aware of privacy, performance and actionability of the data.
95//
96
97#include "jitpch.h"
98#include "compiler.h"
99
100#ifdef FEATURE_TRACELOGGING
101#include "TraceLoggingProvider.h"
102#include "MicrosoftTelemetry.h"
103#include "clrtraceloggingcommon.h"
104#include "fxver.h"
105
106// Since telemetry code could be called under a noway_assert, make sure,
107// we don't call noway_assert again.
108#undef noway_assert
109
110#define BUILD_STR1(x) #x
111#define BUILD_STR2(x) BUILD_STR1(x)
112#define BUILD_MACHINE BUILD_STR2(__BUILDMACHINE__)
113
114// A DLL local instance of the DotNet provider
115TRACELOGGING_DEFINE_PROVIDER(g_hClrJitProvider,
116 CLRJIT_PROVIDER_NAME,
117 CLRJIT_PROVIDER_ID,
118 TraceLoggingOptionMicrosoftTelemetry());
119
120// Threshold to detect if we are hitting too many bad (noway) methods
121// over good methods per process to prevent logging too much data.
122static const double NOWAY_NOISE_RATIO = 0.6; // Threshold of (bad / total) beyond which we'd stop
123 // logging. We'd restart if the pass rate improves.
124static const unsigned NOWAY_SUFFICIENCY_THRESHOLD = 25; // Count of methods beyond which we'd apply percent
125 // threshold
126
127// Initialize Telemetry State
128volatile bool JitTelemetry::s_fProviderRegistered = false;
129volatile UINT32 JitTelemetry::s_uMethodsCompiled = 0;
130volatile UINT32 JitTelemetry::s_uMethodsHitNowayAssert = 0;
131
132// Constructor for telemetry state per compiler instance
133JitTelemetry::JitTelemetry()
134{
135 Initialize(nullptr);
136}
137
138//------------------------------------------------------------------------
139// Initialize: Initialize the object with the compiler instance
140//
141// Description:
142// Compiler instance may not be fully initialized. If you are
143// tracking object data for telemetry, make sure they are initialized
144// in the compiler is ready.
145//
146void JitTelemetry::Initialize(Compiler* c)
147{
148 comp = c;
149 m_pszAssemblyName = "";
150 m_pszScopeName = "";
151 m_pszMethodName = "";
152 m_uMethodHash = 0;
153 m_fMethodInfoCached = false;
154}
155
156//------------------------------------------------------------------------
157// IsTelemetryEnabled: Can we perform JIT telemetry
158//
159// Return Value:
160// Returns "true" if COMPlus_JitTelemetry environment flag is
161// non-zero. Else returns "false".
162//
163//
164/* static */
165bool JitTelemetry::IsTelemetryEnabled()
166{
167 return JitConfig.JitTelemetry() != 0;
168}
169
170//------------------------------------------------------------------------
171// NotifyDllProcessAttach: Notification for DLL load and static initializations
172//
173// Description:
174// Register telemetry provider with the OS.
175//
176// Note:
177// This method can be called twice in NGEN scenario.
178//
179void JitTelemetry::NotifyDllProcessAttach()
180{
181 if (!IsTelemetryEnabled())
182 {
183 return;
184 }
185
186 if (!s_fProviderRegistered)
187 {
188 // Register the provider.
189 TraceLoggingRegister(g_hClrJitProvider);
190 s_fProviderRegistered = true;
191 }
192}
193
194//------------------------------------------------------------------------
195// NotifyDllProcessDetach: Notification for DLL unload and teardown
196//
197// Description:
198// Log the methods compiled data if telemetry is enabled and
199// Unregister telemetry provider with the OS.
200//
201void JitTelemetry::NotifyDllProcessDetach()
202{
203 if (!IsTelemetryEnabled())
204 {
205 return;
206 }
207
208 assert(s_fProviderRegistered); // volatile read
209
210 // Unregister the provider.
211 TraceLoggingUnregister(g_hClrJitProvider);
212}
213
214//------------------------------------------------------------------------
215// NotifyEndOfCompilation: Notification for end of current method
216// compilation.
217//
218// Description:
219// Increment static volatile counters for the current compiled method.
220// This is slightly inaccurate due to lack of synchronization around
221// the counters. Inaccuracy is the tradeoff for JITting cost.
222//
223// Note:
224// 1. Must be called post fully successful compilation of the method.
225// 2. This serves as an effective baseline as how many methods compiled
226// successfully.
227void JitTelemetry::NotifyEndOfCompilation()
228{
229 if (!IsTelemetryEnabled())
230 {
231 return;
232 }
233
234 s_uMethodsCompiled++; // volatile increment
235}
236
237//------------------------------------------------------------------------
238// NotifyNowayAssert: Notification that a noway handling is under-way.
239//
240// Arguments:
241// filename - The JIT source file name's absolute path at the time of
242// building the JIT.
243// line - The line number where the noway assert was hit.
244//
245// Description:
246// If telemetry is enabled, then obtain data to collect from the
247// compiler or the VM and use the tracelogging APIs to write out.
248//
249void JitTelemetry::NotifyNowayAssert(const char* filename, unsigned line)
250{
251 if (!IsTelemetryEnabled())
252 {
253 return;
254 }
255
256 s_uMethodsHitNowayAssert++;
257
258 // Check if our assumption that noways are rare is invalid for this
259 // process. If so, return early than logging too much data.
260 unsigned noways = s_uMethodsHitNowayAssert;
261 unsigned attempts = max(1, s_uMethodsCompiled + noways);
262 double ratio = (noways / ((double)attempts));
263 if (noways > NOWAY_SUFFICIENCY_THRESHOLD && ratio > NOWAY_NOISE_RATIO)
264 {
265 return;
266 }
267
268 assert(comp);
269
270 UINT32 nowayIndex = s_uMethodsHitNowayAssert;
271 UINT32 codeSize = 0;
272 INT32 minOpts = -1;
273 const char* lastPhase = "";
274 if (comp != nullptr)
275 {
276 codeSize = comp->info.compILCodeSize;
277 minOpts = comp->opts.IsMinOptsSet() ? comp->opts.MinOpts() : -1;
278 lastPhase = PhaseNames[comp->previousCompletedPhase];
279 }
280
281 CacheCurrentMethodInfo();
282
283 TraceLoggingWrite(g_hClrJitProvider, "CLRJIT.NowayAssert",
284
285 TraceLoggingUInt32(codeSize, "IL_CODE_SIZE"), TraceLoggingInt32(minOpts, "MINOPTS_MODE"),
286 TraceLoggingString(lastPhase, "PREVIOUS_COMPLETED_PHASE"),
287
288 TraceLoggingString(m_pszAssemblyName, "ASSEMBLY_NAME"),
289 TraceLoggingString(m_pszMethodName, "METHOD_NAME"),
290 TraceLoggingString(m_pszScopeName, "METHOD_SCOPE"),
291 TraceLoggingUInt32(m_uMethodHash, "METHOD_HASH"),
292
293 TraceLoggingString(filename, "FILENAME"), TraceLoggingUInt32(line, "LINE"),
294 TraceLoggingUInt32(nowayIndex, "NOWAY_INDEX"),
295
296 TraceLoggingString(TARGET_READABLE_NAME, "ARCH"),
297 TraceLoggingString(VER_FILEVERSION_STR, "VERSION"), TraceLoggingString(BUILD_MACHINE, "BUILD"),
298 TraceLoggingString(VER_COMMENTS_STR, "FLAVOR"),
299
300 TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES));
301}
302
303//------------------------------------------------------------------------
304// CacheCurrentMethodInfo: Cache the method/assembly/scope name info.
305//
306// Description:
307// Obtain the method information if not already cached, for the
308// method under compilation from the compiler. This includes:
309//
310// Method name, assembly name, scope name, method hash.
311//
312void JitTelemetry::CacheCurrentMethodInfo()
313{
314 if (m_fMethodInfoCached)
315 {
316 return;
317 }
318
319 assert(comp);
320 if (comp != nullptr)
321 {
322 comp->compGetTelemetryDefaults(&m_pszAssemblyName, &m_pszScopeName, &m_pszMethodName, &m_uMethodHash);
323 assert(m_pszAssemblyName);
324 assert(m_pszScopeName);
325 assert(m_pszMethodName);
326 }
327
328 // Set cached to prevent getting this twice.
329 m_fMethodInfoCached = true;
330}
331
332//------------------------------------------------------------------------
333// compGetTelemetryDefaults: Obtain information specific to telemetry
334// from the JIT-interface.
335//
336// Arguments:
337// assemblyName - Pointer to hold assembly name upon return
338// scopeName - Pointer to hold scope name upon return
339// methodName - Pointer to hold method name upon return
340// methodHash - Pointer to hold method hash upon return
341//
342// Description:
343// Obtains from the JIT EE interface the information for the
344// current method under compilation.
345//
346// Warning:
347// The eeGetMethodName call could be expensive for generic
348// methods, so call this method only when there is less impact
349// to throughput.
350//
351void Compiler::compGetTelemetryDefaults(const char** assemblyName,
352 const char** scopeName,
353 const char** methodName,
354 unsigned* methodHash)
355{
356 if (info.compMethodHnd != nullptr)
357 {
358 __try
359 {
360
361 // Expensive calls, call infrequently or in exceptional scenarios.
362 *methodHash = info.compCompHnd->getMethodHash(info.compMethodHnd);
363 *methodName = eeGetMethodName(info.compMethodHnd, scopeName);
364
365 // SuperPMI needs to implement record/replay of these method calls.
366 *assemblyName = info.compCompHnd->getAssemblyName(
367 info.compCompHnd->getModuleAssembly(info.compCompHnd->getClassModule(info.compClassHnd)));
368 }
369 __except (EXCEPTION_EXECUTE_HANDLER)
370 {
371 }
372 }
373
374 // If the JIT interface methods init-ed these values to nullptr,
375 // make sure they are set to empty string.
376 if (*methodName == nullptr)
377 {
378 *methodName = "";
379 }
380 if (*scopeName == nullptr)
381 {
382 *scopeName = "";
383 }
384 if (*assemblyName == nullptr)
385 {
386 *assemblyName = "";
387 }
388}
389
390#endif // FEATURE_TRACELOGGING
391