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#include "stdafx.h"
6#include "perflog.h"
7#include "jitperf.h"
8#include <limits.h>
9#include "sstring.h"
10
11//=============================================================================
12// ALL THE PERF LOG CODE IS COMPILED ONLY IF ENABLE_PERF_LOG IS DEFINED.
13#if defined (ENABLE_PERF_LOG)
14//=============================================================================
15
16//-----------------------------------------------------------------------------
17// Widechar strings representing the units in UnitOfMeasure. *** Keep in sync ***
18// with the array defined in PerfLog.cpp
19const wchar_t * const wszUnitOfMeasureDescr[MAX_UNITS_OF_MEASURE] =
20{
21 W(""),
22 W("sec"),
23 W("Bytes"),
24 W("KBytes"),
25 W("KBytes/sec"),
26 W("cycles")
27};
28
29//-----------------------------------------------------------------------------
30// Widechar strings representing the "direction" property of above units.
31// *** Keep in sync *** with the array defined in PerfLog.cpp
32// "Direction" property is false if an increase in the value of the counter indicates
33// a degrade.
34// "Direction" property is true if an increase in the value of the counter indicates
35// an improvement.
36const wchar_t * const wszIDirection[MAX_UNITS_OF_MEASURE] =
37{
38 W("false"),
39 W("false"),
40 W("false"),
41 W("false"),
42 W("true"),
43 W("false")
44};
45
46//-----------------------------------------------------------------------------
47// Initialize static variables of the PerfLog class.
48bool PerfLog::m_perfLogInit = false;
49wchar_t PerfLog::m_wszOutStr_1[];
50DWORD PerfLog::m_dwWriteByte = 0;
51int PerfLog::m_fLogPerfData = 0;
52HANDLE PerfLog::m_hPerfLogFileHandle = 0;
53bool PerfLog::m_perfAutomationFormat = false;
54bool PerfLog::m_commaSeparatedFormat = false;
55
56//-----------------------------------------------------------------------------
57// Initliaze perf logging. Must be called before calling PERFLOG (x)...
58void PerfLog::PerfLogInitialize()
59{
60 LIMITED_METHOD_CONTRACT;
61
62 // Make sure we are called only once.
63 if (m_perfLogInit)
64 {
65 return;
66 }
67
68 // First check for special cases:
69
70#if defined(ENABLE_JIT_PERF)
71 // Checks the JIT_PERF_OUTPUT env var and sets g_fJitPerfOn.
72 InitJitPerf();
73#endif
74
75#ifdef WS_PERF
76 // Private working set perf stats
77 InitWSPerf();
78#endif // WS_PERF
79
80 // Put other special cases here.
81
82 // <TODO>@TODO agk: clean this logic a bit</TODO>
83 // Special cases considered. Now turn on loggin if any of above want logging
84 // or if PERF_OUTPUT says so.
85
86 InlineSString<4> lpszValue;
87 // Read the env var PERF_OUTPUT and if set continue.
88 m_fLogPerfData = WszGetEnvironmentVariable (W("PERF_OUTPUT"), lpszValue);
89
90#if defined(ENABLE_JIT_PERF)
91 if (!m_fLogPerfData)
92 {
93 // Make sure that JIT perf was not requested.
94 if (!g_fJitPerfOn)
95 return;
96
97 // JIT perf stats are needed so set the flags also.
98 m_fLogPerfData = 1;
99 }
100#endif
101
102 // See if we want to output to the database
103 PathString _lpszValue;
104 DWORD _cchValue = 10; // 11 - 1
105 _cchValue = WszGetEnvironmentVariable (W("PerfOutput"), _lpszValue);
106 if (_cchValue && (wcscmp (_lpszValue, W("DBase")) == 0))
107 m_perfAutomationFormat = true;
108 if (_cchValue && (wcscmp (_lpszValue, W("CSV")) == 0))
109 m_commaSeparatedFormat = true;
110
111 if (PerfAutomationFormat() || CommaSeparatedFormat())
112 {
113 // Hardcoded file name for spitting the perf auotmation formatted perf data. Open
114 // the file here for writing and close in PerfLogDone().
115 m_hPerfLogFileHandle = WszCreateFile (
116#ifdef PLATFORM_UNIX
117 W("/tmp/PerfData.dat"),
118#else
119 W("C:\\PerfData.dat"),
120#endif
121 GENERIC_WRITE,
122 FILE_SHARE_WRITE,
123 0,
124 OPEN_ALWAYS,
125 FILE_ATTRIBUTE_NORMAL,
126 0);
127
128 // check return value
129 if(m_hPerfLogFileHandle == INVALID_HANDLE_VALUE)
130 {
131 m_fLogPerfData = 0;
132 goto ErrExit;
133 }
134
135 // Make sure we append to the file. <TODO>@TODO agk: Is this necessary?</TODO>
136 if(SetFilePointer (m_hPerfLogFileHandle, 0, NULL, FILE_END) == INVALID_SET_FILE_POINTER )
137 {
138 CloseHandle (m_hPerfLogFileHandle);
139 m_fLogPerfData = 0;
140 goto ErrExit;
141 }
142 }
143
144 m_perfLogInit = true;
145
146ErrExit:
147 return;
148}
149
150// Wrap up...
151void PerfLog::PerfLogDone()
152{
153 LIMITED_METHOD_CONTRACT;
154
155#if defined(ENABLE_JIT_PERF)
156 DoneJitPerfStats();
157#endif
158
159#ifdef WS_PERF
160 // Private working set perf
161 OutputWSPerfStats();
162#endif // WS_PERF
163
164 if (CommaSeparatedFormat())
165 {
166 if (0 == WriteFile (m_hPerfLogFileHandle, "\n", (DWORD)strlen("\n"), &m_dwWriteByte, NULL))
167 printf("ERROR: Could not write to perf log.\n");
168 }
169
170 if (PerfLoggingEnabled())
171 CloseHandle (m_hPerfLogFileHandle);
172}
173
174void PerfLog::OutToStdout(__in_z const wchar_t *wszName, UnitOfMeasure unit, __in_opt const wchar_t *wszDescr)
175{
176 LIMITED_METHOD_CONTRACT;
177
178 wchar_t wszOutStr_2[PRINT_STR_LEN];
179
180 if (wszDescr)
181 _snwprintf_s(wszOutStr_2, PRINT_STR_LEN, PRINT_STR_LEN - 1, W(" (%s)\n"), wszDescr);
182 else
183 _snwprintf_s(wszOutStr_2, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("\n"));
184
185 printf("%S", m_wszOutStr_1);
186 printf("%S", wszOutStr_2);
187}
188
189void PerfLog::OutToPerfFile(__in_z const wchar_t *wszName, UnitOfMeasure unit, __in_opt const wchar_t *wszDescr)
190{
191 LIMITED_METHOD_CONTRACT;
192
193 char szPrintStr[PRINT_STR_LEN];
194
195 if (CommaSeparatedFormat())
196 {
197 if (WszWideCharToMultiByte (CP_ACP, 0, m_wszOutStr_1, -1, szPrintStr, PRINT_STR_LEN-1, 0, 0) ) {
198 if (0 == WriteFile (m_hPerfLogFileHandle, szPrintStr, (DWORD)strlen(szPrintStr), &m_dwWriteByte, NULL))
199 printf("ERROR: Could not write to perf log.\n");
200 }
201 else
202 wprintf(W("ERROR: Could not do string conversion.\n"));
203 }
204 else
205 {
206 wchar_t wszOutStr_2[PRINT_STR_LEN];
207
208 // workaround. The formats for ExecTime is slightly different from a custom value.
209 if (wcscmp(wszName, W("ExecTime")) == 0)
210 _snwprintf_s(wszOutStr_2, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("ExecUnitDescr=%s\nExecIDirection=%s\n"), wszDescr, wszIDirection[unit]);
211 else
212 {
213 if (wszDescr)
214 _snwprintf_s(wszOutStr_2, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s Descr=%s\n%s Unit Descr=None\n%s IDirection=%s\n"), wszName, wszDescr, wszName, wszName, wszIDirection[unit]);
215 else
216 _snwprintf_s(wszOutStr_2, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s Descr=None\n%s Unit Descr=None\n%s IDirection=%s\n"), wszName, wszName, wszName, wszIDirection[unit]);
217 }
218
219 // Write both pieces to the file.
220 if(WszWideCharToMultiByte (CP_ACP, 0, m_wszOutStr_1, -1, szPrintStr, PRINT_STR_LEN-1, 0, 0) ) {
221 if (0 == WriteFile (m_hPerfLogFileHandle, szPrintStr, (DWORD)strlen(szPrintStr), &m_dwWriteByte, NULL))
222 printf("ERROR: Could not write to perf log.\n");
223 }
224 else
225 wprintf(W("ERROR: Could not do string conversion.\n"));
226
227 if(WszWideCharToMultiByte (CP_ACP, 0, wszOutStr_2, -1, szPrintStr, PRINT_STR_LEN-1, 0, 0)) {
228 if (0 == WriteFile (m_hPerfLogFileHandle, szPrintStr, (DWORD)strlen(szPrintStr), &m_dwWriteByte, NULL))
229 printf("ERROR: Could not write to perf log.\n");
230 }
231 else
232 wprintf(W("ERROR: Could not do string conversion.\n"));
233 }
234}
235
236// Output stats in pretty print to stdout and perf automation format to file
237// handle m_hPerfLogFileHandle
238void PerfLog::Log(__in_z const wchar_t *wszName, UINT64 val, UnitOfMeasure unit, __in_opt const wchar_t *wszDescr)
239{
240 LIMITED_METHOD_CONTRACT;
241
242 // Format the output into two pieces: The first piece is formatted here, rest in OutToStdout.
243 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%-30s%12.3I64u %s"), wszName, val, wszUnitOfMeasureDescr[unit]);
244 OutToStdout (wszName, unit, wszDescr);
245
246 // Format the output into two pieces: The first piece is formatted here, rest in OutToPerfFile
247 if (CommaSeparatedFormat())
248 {
249 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s;%0.3I64u;"), wszName, val);
250 OutToPerfFile (wszName, unit, wszDescr);
251 }
252
253 if (PerfAutomationFormat())
254 {
255 // workaround, Special case for ExecTime. since the format is slightly different than for custom value.
256 if (wcscmp(wszName, W("ExecTime")) == 0)
257 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s=%0.3I64u\nExecUnit=%s\n"), wszName, val, wszUnitOfMeasureDescr[unit]);
258 else
259 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s=%0.3I64u\n%s Unit=%s\n"), wszName, val, wszName, wszUnitOfMeasureDescr[unit]);
260 OutToPerfFile (wszName, unit, wszDescr);
261 }
262}
263
264// Output stats in pretty print to stdout and perf automation format to file
265// handle m_hPerfLogFileHandle
266void PerfLog::Log(__in_z const wchar_t *wszName, double val, UnitOfMeasure unit, __in_opt const wchar_t *wszDescr)
267{
268 LIMITED_METHOD_CONTRACT;
269
270 // Format the output into two pieces: The first piece is formatted here, rest in OutToStdout.
271 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%-30s%12.3g %s"), wszName, val, wszUnitOfMeasureDescr[unit]);
272 OutToStdout (wszName, unit, wszDescr);
273
274 // Format the output into two pieces: The first piece is formatted here, rest in OutToPerfFile
275 if (CommaSeparatedFormat())
276 {
277 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s;%0.3g;"), wszName, val);
278 OutToPerfFile (wszName, unit, wszDescr);
279 }
280
281 if (PerfAutomationFormat())
282 {
283 // workaround, Special case for ExecTime. since the format is slightly different than for custom value.
284 if (wcscmp(wszName, W("ExecTime")) == 0)
285 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s=%0.3g\nExecUnit=%s\n"), wszName, val, wszUnitOfMeasureDescr[unit]);
286 else
287 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s=%0.3g\n%s Unit=%s\n"), wszName, val, wszName, wszUnitOfMeasureDescr[unit]);
288 OutToPerfFile (wszName, unit, wszDescr);
289 }
290}
291
292// Output stats in pretty print to stdout and perf automation format to file
293// handle m_hPerfLogFileHandle
294void PerfLog::Log(__in_z const wchar_t *wszName, UINT32 val, UnitOfMeasure unit, __in_opt const wchar_t *wszDescr)
295{
296 LIMITED_METHOD_CONTRACT;
297
298 // Format the output into two pieces: The first piece is formatted here, rest in OutToStdout.
299
300 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%-30s%12d %s"), wszName, val, wszUnitOfMeasureDescr[unit]);
301 OutToStdout (wszName, unit, wszDescr);
302
303 // Format the output into two pieces: The first piece is formatted here, rest in OutToPerfFile
304 if (CommaSeparatedFormat())
305 {
306 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s;%d;"), wszName, val);
307 OutToPerfFile (wszName, unit, wszDescr);
308 }
309
310 if (PerfAutomationFormat())
311 {
312 // workaround, Special case for ExecTime. since the format is slightly different than for custom value.
313 if (wcscmp(wszName, W("ExecTime")) == 0)
314 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s=%0.3d\nExecUnit=%s\n"), wszName, val, wszUnitOfMeasureDescr[unit]);
315 else
316 _snwprintf_s(m_wszOutStr_1, PRINT_STR_LEN, PRINT_STR_LEN - 1, W("%s=%0.3d\n%s Unit=%s\n"), wszName, val, wszName, wszUnitOfMeasureDescr[unit]);
317 OutToPerfFile (wszName, unit, wszDescr);
318 }
319}
320
321
322//=============================================================================
323// ALL THE PERF LOG CODE IS COMPILED ONLY IF THE ENABLE_PERF_LOG WAS DEFINED.
324#endif // ENABLE_PERF_LOG
325//=============================================================================
326
327