src/utilcode/perflog.cpp

   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
  19 const 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.
  36 const 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.
  48 bool PerfLog::m_perfLogInit = false;
  49 wchar_t PerfLog::m_wszOutStr_1[];
  50 DWORD PerfLog::m_dwWriteByte = 0;
  51 int PerfLog::m_fLogPerfData = 0;
  52 HANDLE PerfLog::m_hPerfLogFileHandle = 0;
  53 bool PerfLog::m_perfAutomationFormat = false;
  54 bool PerfLog::m_commaSeparatedFormat = false;
  55
  56 //-----------------------------------------------------------------------------
  57 // Initliaze perf logging. Must be called before calling PERFLOG (x)...
  58 void 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
 146 ErrExit:
 147     return;
 148 }
 149
 150 // Wrap up...
 151 void 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
 174 void 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
 189 void 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
 238 void 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
 266 void 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
 294 void 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