1 /************************************************************************ 2 * file name : event_trace_win.cpp 3 * ----------------- : 4 * creation time : 2016/09/04 5 * author : Victor Zarubkin 6 * email : v.s.zarubkin@gmail.com 7 * ----------------- : 8 * description : The file contains implementation of EasyEventTracer class used for tracing 9 * : Windows system events to get context switches. 10 * ----------------- : 11 * change log : * 2016/09/04 Victor Zarubkin: initial commit. 12 * : 13 * : * 2016/09/13 Victor Zarubkin: get process id and process name 14 * : of the owner of thread with id == CSwitch::NewThreadId. 15 * : 16 * : * 2016/09/17 Victor Zarubkin: added log messages printing. 17 * ----------------- : 18 * license : Lightweight profiler library for c++ 19 * : Copyright(C) 2016-2017 Sergey Yagovtsev, Victor Zarubkin 20 * : 21 * : Licensed under either of 22 * : * MIT license (LICENSE.MIT or http://opensource.org/licenses/MIT) 23 * : * Apache License, Version 2.0, (LICENSE.APACHE or http://www.apache.org/licenses/LICENSE-2.0) 24 * : at your option. 25 * : 26 * : The MIT License 27 * : 28 * : Permission is hereby granted, free of charge, to any person obtaining a copy 29 * : of this software and associated documentation files (the "Software"), to deal 30 * : in the Software without restriction, including without limitation the rights 31 * : to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies 32 * : of the Software, and to permit persons to whom the Software is furnished 33 * : to do so, subject to the following conditions: 34 * : 35 * : The above copyright notice and this permission notice shall be included in all 36 * : copies or substantial portions of the Software. 37 * : 38 * : THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, 39 * : INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR 40 * : PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE 41 * : LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, 42 * : TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE 43 * : USE OR OTHER DEALINGS IN THE SOFTWARE. 44 * : 45 * : The Apache License, Version 2.0 (the "License") 46 * : 47 * : You may not use this file except in compliance with the License. 48 * : You may obtain a copy of the License at 49 * : 50 * : http://www.apache.org/licenses/LICENSE-2.0 51 * : 52 * : Unless required by applicable law or agreed to in writing, software 53 * : distributed under the License is distributed on an "AS IS" BASIS, 54 * : WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 55 * : See the License for the specific language governing permissions and 56 * : limitations under the License. 57 ************************************************************************/ 58 59 #ifdef _WIN32 60 #include <memory.h> 61 #include <chrono> 62 #include <unordered_map> 63 #include <easy/profiler.h> 64 #include "profile_manager.h" 65 #include "current_time.h" 66 67 #include "event_trace_win.h" 68 #include <Psapi.h> 69 70 #ifdef __MINGW32__ 71 #include <processthreadsapi.h> 72 #endif 73 74 //#include <Shellapi.h> 75 76 #if EASY_OPTION_LOG_ENABLED != 0 77 # include <iostream> 78 79 # ifndef EASY_ERRORLOG 80 # define EASY_ERRORLOG ::std::cerr 81 # endif 82 83 # ifndef EASY_LOG 84 # define EASY_LOG ::std::cerr 85 # endif 86 87 # ifndef EASY_ERROR 88 # define EASY_ERROR(LOG_MSG) EASY_ERRORLOG << "EasyProfiler ERROR: " << LOG_MSG 89 # endif 90 91 # ifndef EASY_WARNING 92 # define EASY_WARNING(LOG_MSG) EASY_ERRORLOG << "EasyProfiler WARNING: " << LOG_MSG 93 # endif 94 95 # ifndef EASY_LOGMSG 96 # define EASY_LOGMSG(LOG_MSG) EASY_LOG << "EasyProfiler INFO: " << LOG_MSG 97 # endif 98 99 # ifndef EASY_LOG_ONLY 100 # define EASY_LOG_ONLY(CODE) CODE 101 # endif 102 103 #else 104 105 # ifndef EASY_ERROR 106 # define EASY_ERROR(LOG_MSG) 107 # endif 108 109 # ifndef EASY_WARNING 110 # define EASY_WARNING(LOG_MSG) 111 # endif 112 113 # ifndef EASY_LOGMSG 114 # define EASY_LOGMSG(LOG_MSG) 115 # endif 116 117 # ifndef EASY_LOG_ONLY 118 # define EASY_LOG_ONLY(CODE) 119 # endif 120 121 #endif 122 123 ////////////////////////////////////////////////////////////////////////// 124 ////////////////////////////////////////////////////////////////////////// 125 126 //extern ProfileManager& MANAGER; 127 #define MANAGER ProfileManager::instance() 128 129 extern const ::profiler::color_t EASY_COLOR_INTERNAL_EVENT; 130 131 #ifdef __MINGW32__ 132 ::std::atomic<uint64_t> TRACING_END_TIME = ATOMIC_VAR_INIT(~0ULL); 133 char KERNEL_LOGGER[] = KERNEL_LOGGER_NAME; 134 #else 135 ::std::atomic_uint64_t TRACING_END_TIME = ATOMIC_VAR_INIT(~0ULL); 136 #endif 137 138 namespace profiler { 139 140 const decltype(EVENT_DESCRIPTOR::Opcode) SWITCH_CONTEXT_OPCODE = 36; 141 const int RAW_TIMESTAMP_TIME_TYPE = 1; 142 143 ////////////////////////////////////////////////////////////////////////// 144 145 struct ProcessInfo { 146 std::string name; 147 processid_t id = 0; 148 int8_t valid = 0; 149 }; 150 151 ////////////////////////////////////////////////////////////////////////// 152 153 // CSwitch class 154 // See https://msdn.microsoft.com/en-us/library/windows/desktop/aa964744(v=vs.85).aspx 155 // EventType = 36 156 struct CSwitch 157 { 158 uint32_t NewThreadId; 159 uint32_t OldThreadId; 160 int8_t NewThreadPriority; 161 int8_t OldThreadPriority; 162 uint8_t PreviousCState; 163 int8_t SpareByte; 164 int8_t OldThreadWaitReason; 165 int8_t OldThreadWaitMode; 166 int8_t OldThreadState; 167 int8_t OldThreadWaitIdealProcessor; 168 uint32_t NewThreadWaitTime; 169 uint32_t Reserved; 170 }; 171 172 ////////////////////////////////////////////////////////////////////////// 173 174 struct do_not_calc_hash { operator ()profiler::do_not_calc_hash175 template <class T> inline size_t operator()(T _value) const { 176 return static_cast<size_t>(_value); 177 } 178 }; 179 180 typedef ::std::unordered_map<decltype(CSwitch::NewThreadId), ProcessInfo*, do_not_calc_hash> thread_process_info_map; 181 typedef ::std::unordered_map<processid_t, ProcessInfo, do_not_calc_hash> process_info_map; 182 183 // Using static is safe because processTraceEvent() is called from one thread 184 process_info_map PROCESS_INFO_TABLE; __anonc88d18660102()185 thread_process_info_map THREAD_PROCESS_INFO_TABLE = ([](){ thread_process_info_map initial; initial[0U] = nullptr; return ::std::move(initial); })(); 186 187 ////////////////////////////////////////////////////////////////////////// 188 processTraceEvent(PEVENT_RECORD _traceEvent)189 void WINAPI processTraceEvent(PEVENT_RECORD _traceEvent) 190 { 191 if (_traceEvent->EventHeader.EventDescriptor.Opcode != SWITCH_CONTEXT_OPCODE) 192 return; 193 194 if (sizeof(CSwitch) != _traceEvent->UserDataLength) 195 return; 196 197 EASY_FUNCTION(EASY_COLOR_INTERNAL_EVENT, ::profiler::OFF); 198 199 auto _contextSwitchEvent = reinterpret_cast<CSwitch*>(_traceEvent->UserData); 200 const auto time = static_cast<::profiler::timestamp_t>(_traceEvent->EventHeader.TimeStamp.QuadPart); 201 if (time > TRACING_END_TIME.load(::std::memory_order_acquire)) 202 return; 203 204 DWORD pid = 0; 205 const char* process_name = ""; 206 207 // Trying to get target process name and id 208 auto it = THREAD_PROCESS_INFO_TABLE.find(_contextSwitchEvent->NewThreadId); 209 if (it == THREAD_PROCESS_INFO_TABLE.end()) 210 { 211 auto hThread = OpenThread(THREAD_QUERY_LIMITED_INFORMATION, FALSE, _contextSwitchEvent->NewThreadId); 212 if (hThread != nullptr) 213 { 214 pid = GetProcessIdOfThread(hThread); 215 auto pinfo = &PROCESS_INFO_TABLE[pid]; 216 217 if (pinfo->valid == 0) 218 { 219 if (pinfo->name.empty()) 220 { 221 static char numbuf[128] = {}; 222 sprintf(numbuf, "%u", pid); 223 pinfo->name = numbuf; 224 pinfo->id = pid; 225 } 226 227 /* 228 According to documentation, using GetModuleBaseName() requires 229 PROCESS_QUERY_INFORMATION | PROCESS_VM_READ access rights. 230 But it works fine with PROCESS_QUERY_LIMITED_INFORMATION instead of PROCESS_QUERY_INFORMATION. 231 232 See https://msdn.microsoft.com/en-us/library/windows/desktop/ms683196(v=vs.85).aspx 233 */ 234 235 //auto hProc = OpenProcess(PROCESS_QUERY_INFORMATION | PROCESS_VM_READ, FALSE, pid); 236 //if (hProc == nullptr) 237 auto hProc = OpenProcess(PROCESS_QUERY_LIMITED_INFORMATION | PROCESS_VM_READ, FALSE, pid); 238 if (hProc != nullptr) 239 { 240 static TCHAR buf[MAX_PATH] = {}; // Using static is safe because processTraceEvent() is called from one thread 241 auto len = GetModuleBaseName(hProc, 0, buf, MAX_PATH); 242 243 if (len != 0) 244 { 245 pinfo->name.reserve(pinfo->name.size() + 2 + len); 246 pinfo->name.append(" ", 1); 247 pinfo->name.append(buf, len); 248 pinfo->valid = 1; 249 } 250 251 CloseHandle(hProc); 252 } 253 else 254 { 255 //auto err = GetLastError(); 256 //printf("OpenProcess(%u) fail: GetLastError() == %u\n", pid, err); 257 pinfo->valid = -1; 258 259 if (pid == 4) { 260 pinfo->name.reserve(pinfo->name.size() + 8); 261 pinfo->name.append(" System", 7); 262 } 263 } 264 } 265 266 process_name = pinfo->name.c_str(); 267 THREAD_PROCESS_INFO_TABLE[_contextSwitchEvent->NewThreadId] = pinfo; 268 269 CloseHandle(hThread); 270 } 271 else 272 { 273 //printf("Can not OpenThread(%u);\n", _contextSwitchEvent->NewThreadId); 274 THREAD_PROCESS_INFO_TABLE[_contextSwitchEvent->NewThreadId] = nullptr; 275 } 276 } 277 else 278 { 279 auto pinfo = it->second; 280 if (pinfo != nullptr) 281 process_name = pinfo->name.c_str(); 282 else if (it->first == 0) 283 process_name = "System Idle"; 284 else if (it->first == 4) 285 process_name = "System"; 286 } 287 288 MANAGER.beginContextSwitch(_contextSwitchEvent->OldThreadId, time, _contextSwitchEvent->NewThreadId, process_name); 289 MANAGER.endContextSwitch(_contextSwitchEvent->NewThreadId, pid, time); 290 } 291 292 ////////////////////////////////////////////////////////////////////////// 293 294 #ifndef EASY_MAGIC_STATIC_AVAILABLE 295 class EasyEventTracerInstance { 296 friend EasyEventTracer; 297 EasyEventTracer instance; 298 } EASY_EVENT_TRACER; 299 #endif 300 instance()301 EasyEventTracer& EasyEventTracer::instance() 302 { 303 #ifndef EASY_MAGIC_STATIC_AVAILABLE 304 return EASY_EVENT_TRACER.instance; 305 #else 306 static EasyEventTracer tracer; 307 return tracer; 308 #endif 309 } 310 EasyEventTracer()311 EasyEventTracer::EasyEventTracer() 312 { 313 m_lowPriority = ATOMIC_VAR_INIT(EASY_OPTION_LOW_PRIORITY_EVENT_TRACING); 314 } 315 ~EasyEventTracer()316 EasyEventTracer::~EasyEventTracer() 317 { 318 disable(); 319 } 320 isLowPriority() const321 bool EasyEventTracer::isLowPriority() const 322 { 323 return m_lowPriority.load(::std::memory_order_acquire); 324 } 325 setLowPriority(bool _value)326 void EasyEventTracer::setLowPriority(bool _value) 327 { 328 m_lowPriority.store(_value, ::std::memory_order_release); 329 } 330 setPrivilege(HANDLE hToken,LPCSTR _privelegeName)331 bool setPrivilege(HANDLE hToken, LPCSTR _privelegeName) 332 { 333 bool success = false; 334 335 if (hToken) 336 { 337 LUID privilegyId; 338 if (LookupPrivilegeValue(NULL, _privelegeName, &privilegyId)) 339 { 340 TOKEN_PRIVILEGES tokenPrivilege; 341 tokenPrivilege.PrivilegeCount = 1; 342 tokenPrivilege.Privileges[0].Luid = privilegyId; 343 tokenPrivilege.Privileges[0].Attributes = SE_PRIVILEGE_ENABLED; 344 success = AdjustTokenPrivileges(hToken, FALSE, &tokenPrivilege, sizeof(TOKEN_PRIVILEGES), NULL, NULL) != FALSE; 345 } 346 } 347 348 EASY_LOG_ONLY( 349 if (!success) 350 EASY_WARNING("Failed to set " << _privelegeName << " privelege for the application.\n"); 351 ) 352 353 return success; 354 } 355 setProcessPrivileges()356 void EasyEventTracer::setProcessPrivileges() 357 { 358 static bool alreadySet = false; 359 if (alreadySet) 360 return; 361 362 alreadySet = true; 363 364 HANDLE hToken = nullptr; 365 if (OpenProcessToken(GetCurrentProcess(), TOKEN_ADJUST_PRIVILEGES | TOKEN_QUERY, &hToken)) 366 { 367 #if EASY_OPTION_LOG_ENABLED != 0 368 const bool success = setPrivilege(hToken, SE_DEBUG_NAME); 369 if (!success) 370 EASY_WARNING("Some context switch events could not get process name.\n"); 371 #else 372 setPrivilege(hToken, SE_DEBUG_NAME); 373 #endif 374 375 CloseHandle(hToken); 376 } 377 EASY_LOG_ONLY( 378 else { 379 EASY_WARNING("Failed to open process to adjust priveleges.\n"); 380 } 381 ) 382 } 383 startTrace(bool _force,int _step)384 ::profiler::EventTracingEnableStatus EasyEventTracer::startTrace(bool _force, int _step) 385 { 386 auto startTraceResult = StartTrace(&m_sessionHandle, KERNEL_LOGGER_NAME, props()); 387 switch (startTraceResult) 388 { 389 case ERROR_SUCCESS: 390 return EVENT_TRACING_LAUNCHED_SUCCESSFULLY; 391 392 case ERROR_ALREADY_EXISTS: 393 { 394 if (_force) 395 { 396 // Try to stop another event tracing session to force launch self session. 397 398 if (_step == 0) 399 { 400 /* 401 According to https://msdn.microsoft.com/en-us/library/windows/desktop/aa363696(v=vs.85).aspx 402 SessionHandle is ignored (and could be NULL) if SessionName is not NULL, 403 and you only need to set the Wnode.BufferSize, Wnode.Guid, LoggerNameOffset, and LogFileNameOffset 404 in EVENT_TRACE_PROPERTIES structure if ControlCode is EVENT_TRACE_CONTROL_STOP. 405 All data is already set for m_properties to the moment. Simply copy m_properties and use the copy. 406 407 This method supposed to be faster than launching console window and executing shell command, 408 but if that would not work, return to using shell command "logman stop". 409 */ 410 411 // static is safe because we are guarded by spin-lock m_spin 412 static Properties p = ([]{ Properties prp; strncpy(prp.sessionName, KERNEL_LOGGER_NAME, sizeof(prp.sessionName)); return prp; })(); 413 p.base = m_properties.base; // Use copy of m_properties to make sure m_properties will not be changed 414 415 // Stop another session 416 ControlTrace((TRACEHANDLE)NULL, KERNEL_LOGGER_NAME, reinterpret_cast<EVENT_TRACE_PROPERTIES*>(&p), EVENT_TRACE_CONTROL_STOP); 417 418 // Console window variant: 419 //if (32 >= (int)ShellExecute(NULL, NULL, "logman", "stop \"" KERNEL_LOGGER_NAME "\" -ets", NULL, SW_HIDE)) 420 // return EVENT_TRACING_WAS_LAUNCHED_BY_SOMEBODY_ELSE; 421 } 422 423 if (_step < 4) 424 { 425 // Command executed successfully. Wait for a few time until tracing session finish. 426 ::std::this_thread::sleep_for(::std::chrono::milliseconds(500)); 427 return startTrace(true, ++_step); 428 } 429 } 430 431 EASY_ERROR("Event tracing not launched: ERROR_ALREADY_EXISTS. To stop another session execute cmd: logman stop \"" << KERNEL_LOGGER_NAME << "\" -ets\n"); 432 return EVENT_TRACING_WAS_LAUNCHED_BY_SOMEBODY_ELSE; 433 } 434 435 case ERROR_ACCESS_DENIED: 436 EASY_ERROR("Event tracing not launched: ERROR_ACCESS_DENIED. Try to launch your application as Administrator.\n"); 437 return EVENT_TRACING_NOT_ENOUGH_ACCESS_RIGHTS; 438 439 case ERROR_BAD_LENGTH: 440 EASY_ERROR("Event tracing not launched: ERROR_BAD_LENGTH. It seems that your KERNEL_LOGGER_NAME differs from \"" << m_properties.sessionName << "\". Try to re-compile easy_profiler or contact EasyProfiler developers.\n"); 441 return EVENT_TRACING_BAD_PROPERTIES_SIZE; 442 } 443 444 EASY_ERROR("Event tracing not launched: StartTrace() returned " << startTraceResult << ::std::endl); 445 446 return EVENT_TRACING_MISTERIOUS_ERROR; 447 } 448 enable(bool _force)449 ::profiler::EventTracingEnableStatus EasyEventTracer::enable(bool _force) 450 { 451 ::profiler::guard_lock<::profiler::spin_lock> lock(m_spin); 452 if (m_bEnabled) 453 return EVENT_TRACING_LAUNCHED_SUCCESSFULLY; 454 455 /* 456 Trying to set debug privilege for current process 457 to be able to get other process information (process name). 458 */ 459 EasyEventTracer::setProcessPrivileges(); 460 461 // Clear properties 462 memset(&m_properties, 0, sizeof(m_properties)); 463 m_properties.base.Wnode.BufferSize = sizeof(m_properties); 464 m_properties.base.Wnode.Flags = WNODE_FLAG_TRACED_GUID; 465 m_properties.base.Wnode.ClientContext = RAW_TIMESTAMP_TIME_TYPE; 466 m_properties.base.Wnode.Guid = SystemTraceControlGuid; 467 m_properties.base.LoggerNameOffset = sizeof(m_properties.base); 468 m_properties.base.EnableFlags = EVENT_TRACE_FLAG_CSWITCH; 469 m_properties.base.LogFileMode = EVENT_TRACE_REAL_TIME_MODE; 470 471 // Start event tracing 472 auto res = startTrace(_force); 473 if (res != EVENT_TRACING_LAUNCHED_SUCCESSFULLY) 474 return res; 475 476 memset(&m_trace, 0, sizeof(m_trace)); 477 #ifdef __MINGW32__ 478 m_trace.LoggerName = KERNEL_LOGGER; 479 #else 480 m_trace.LoggerName = KERNEL_LOGGER_NAME; 481 #endif 482 m_trace.ProcessTraceMode = PROCESS_TRACE_MODE_REAL_TIME | PROCESS_TRACE_MODE_EVENT_RECORD | PROCESS_TRACE_MODE_RAW_TIMESTAMP; 483 m_trace.EventRecordCallback = ::profiler::processTraceEvent; 484 485 m_openedHandle = OpenTrace(&m_trace); 486 if (m_openedHandle == INVALID_PROCESSTRACE_HANDLE) 487 { 488 EASY_ERROR("Event tracing not launched: OpenTrace() returned invalid handle.\n"); 489 return EVENT_TRACING_OPEN_TRACE_ERROR; 490 } 491 492 /* 493 Have to launch a thread to process events because according to MSDN documentation: 494 495 The ProcessTrace function blocks the thread until it delivers all events, the BufferCallback function returns FALSE, 496 or you call CloseTrace. If the consumer is consuming events in real time, the ProcessTrace function returns after 497 the controller stops the trace session. (Note that there may be a several-second delay before the function returns.) 498 499 https://msdn.microsoft.com/en-us/library/windows/desktop/aa364093(v=vs.85).aspx 500 */ 501 m_processThread = ::std::thread([this](bool _lowPriority) 502 { 503 if (_lowPriority) // Set low priority for event tracing thread 504 SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_LOWEST); 505 EASY_THREAD_SCOPE("EasyProfiler.ETW"); 506 ProcessTrace(&m_openedHandle, 1, 0, 0); 507 508 }, m_lowPriority.load(::std::memory_order_acquire)); 509 510 m_bEnabled = true; 511 512 EASY_LOGMSG("Event tracing launched\n"); 513 return EVENT_TRACING_LAUNCHED_SUCCESSFULLY; 514 } 515 disable()516 void EasyEventTracer::disable() 517 { 518 ::profiler::guard_lock<::profiler::spin_lock> lock(m_spin); 519 if (!m_bEnabled) 520 return; 521 522 EASY_LOGMSG("Event tracing is stopping...\n"); 523 524 TRACING_END_TIME.store(getCurrentTime(), ::std::memory_order_release); 525 526 ControlTrace(m_openedHandle, KERNEL_LOGGER_NAME, props(), EVENT_TRACE_CONTROL_STOP); 527 CloseTrace(m_openedHandle); 528 529 // Wait for ProcessTrace to finish to make sure no processTraceEvent() will be called later. 530 if (m_processThread.joinable()) 531 m_processThread.join(); 532 533 m_bEnabled = false; 534 535 // processTraceEvent() is not called anymore. Clean static maps is safe. 536 PROCESS_INFO_TABLE.clear(); 537 THREAD_PROCESS_INFO_TABLE.clear(); 538 THREAD_PROCESS_INFO_TABLE[0U] = nullptr; 539 540 TRACING_END_TIME.store(~0ULL, ::std::memory_order_release); 541 542 EASY_LOGMSG("Event tracing stopped\n"); 543 } 544 545 } // END of namespace profiler. 546 547 ////////////////////////////////////////////////////////////////////////// 548 ////////////////////////////////////////////////////////////////////////// 549 550 #endif // _WIN32 551