3party/easy_profiler
0
0
Fork 0
mirror of https://github.com/yse/easy_profiler.git synced 2024-12-27 08:41:02 +08:00
Code Issues Projects Releases Wiki Activity

Added more log messages (logging could be enabled via set(EASY_OPTION_LOG ON) in easy_profiler_core/CMakeLists.txt)

Browse Source
This commit is contained in:
Victor Zarubkin 2017-02-08 23:20:09 +03:00
parent 227a23c266
commit 11fbfe65d4
3 changed files with 178 additions and 58 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
easy_profiler_core/CMakeLists.txt
View File

@ -60,7 +60,7 @@ if(WIN32)
MESSAGE(STATUS " Event tracing has low priority = No")
endif(EASY_OPTION_LOW_PRIORITY_EVENT_TRACING)
endif(WIN32)
MESSAGE(STATUS " Print errors to stderr = ${EASY_OPTION_LOG}")
MESSAGE(STATUS " Log messages = ${EASY_OPTION_LOG}")
MESSAGE(STATUS " Use EasyProfiler colors palette = ${EASY_OPTION_PREDEFINED_COLORS}")
MESSAGE(STATUS "END EASY_PROFILER OPTIONS.----------")
MESSAGE(STATUS "")

91
easy_profiler_core/event_trace_win.cpp
View File

@ -59,9 +59,49 @@
#if EASY_OPTION_LOG_ENABLED != 0
# include <iostream>
# ifndef EASY_ETW_LOG
# define EASY_ETW_LOG ::std::cerr
# ifndef EASY_ERRORLOG
# define EASY_ERRORLOG ::std::cerr
# endif
# ifndef EASY_LOG
# define EASY_LOG ::std::cerr
# endif
# ifndef EASY_ERROR
# define EASY_ERROR(LOG_MSG) EASY_ERRORLOG << "EasyProfiler ERROR: " << LOG_MSG
# endif
# ifndef EASY_WARNING
# define EASY_WARNING(LOG_MSG) EASY_ERRORLOG << "EasyProfiler WARNING: " << LOG_MSG
# endif
# ifndef EASY_LOGMSG
# define EASY_LOGMSG(LOG_MSG) EASY_LOG << "EasyProfiler INFO: " << LOG_MSG
# endif
# ifndef EASY_LOG_ONLY
# define EASY_LOG_ONLY(CODE) CODE
# endif
#else
# ifndef EASY_ERROR
# define EASY_ERROR(LOG_MSG)
# endif
# ifndef EASY_WARNING
# define EASY_WARNING(LOG_MSG)
# endif
# ifndef EASY_LOGMSG
# define EASY_LOGMSG(LOG_MSG)
# endif
# ifndef EASY_LOG_ONLY
# define EASY_LOG_ONLY(CODE)
# endif
#endif
//////////////////////////////////////////////////////////////////////////
@ -277,10 +317,10 @@ namespace profiler {
}
}
#if EASY_OPTION_LOG_ENABLED != 0
if (!success)
EASY_ETW_LOG << "Warning: EasyProfiler failed to set " << _privelegeName << " privelege for the application.\n";
#endif
EASY_LOG_ONLY(
if (!success)
EASY_WARNING("Failed to set " << _privelegeName << " privelege for the application.\n");
)
return success;
}
@ -299,19 +339,18 @@ namespace profiler {
#if EASY_OPTION_LOG_ENABLED != 0
const bool success = setPrivilege(hToken, SE_DEBUG_NAME);
if (!success)
EASY_ETW_LOG << "Warning: Some context switch events could not get process name.\n";
EASY_WARNING("Some context switch events could not get process name.\n");
#else
setPrivilege(hToken, SE_DEBUG_NAME);
#endif
CloseHandle(hToken);
}
#if EASY_OPTION_LOG_ENABLED != 0
else
{
EASY_ETW_LOG << "Warning: EasyProfiler failed to open process to adjust priveleges.\n";
}
#endif
EASY_LOG_ONLY(
else {
EASY_WARNING("Failed to open process to adjust priveleges.\n");
}
)
}
::profiler::EventTracingEnableStatus EasyEventTracer::startTrace(bool _force, int _step)
@ -361,28 +400,21 @@ namespace profiler {
}
}
#if EASY_OPTION_LOG_ENABLED != 0
EASY_ETW_LOG << "Error: EasyProfiler.ETW not launched: ERROR_ALREADY_EXISTS. To stop another session execute cmd: logman stop \"" << KERNEL_LOGGER_NAME << "\" -ets\n";
#endif
EASY_ERROR("Event tracing not launched: ERROR_ALREADY_EXISTS. To stop another session execute cmd: logman stop \"" << KERNEL_LOGGER_NAME << "\" -ets\n");
return EVENT_TRACING_WAS_LAUNCHED_BY_SOMEBODY_ELSE;
}
case ERROR_ACCESS_DENIED:
#if EASY_OPTION_LOG_ENABLED != 0
EASY_ETW_LOG << "Error: EasyProfiler.ETW not launched: ERROR_ACCESS_DENIED. Try to launch your application as Administrator.\n";
#endif
EASY_ERROR("Event tracing not launched: ERROR_ACCESS_DENIED. Try to launch your application as Administrator.\n");
return EVENT_TRACING_NOT_ENOUGH_ACCESS_RIGHTS;
case ERROR_BAD_LENGTH:
#if EASY_OPTION_LOG_ENABLED != 0
EASY_ETW_LOG << "Error: EasyProfiler.ETW 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";
#endif
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");
return EVENT_TRACING_BAD_PROPERTIES_SIZE;
}
#if EASY_OPTION_LOG_ENABLED != 0
EASY_ETW_LOG << "Error: EasyProfiler.ETW not launched: StartTrace() returned " << startTraceResult << ::std::endl;
#endif
EASY_ERROR("Event tracing not launched: StartTrace() returned " << startTraceResult << ::std::endl);
return EVENT_TRACING_MISTERIOUS_ERROR;
}
@ -421,9 +453,7 @@ namespace profiler {
m_openedHandle = OpenTrace(&m_trace);
if (m_openedHandle == INVALID_PROCESSTRACE_HANDLE)
{
#if EASY_OPTION_LOG_ENABLED != 0
EASY_ETW_LOG << "Error: EasyProfiler.ETW not launched: OpenTrace() returned invalid handle.\n";
#endif
EASY_ERROR("Event tracing not launched: OpenTrace() returned invalid handle.\n");
return EVENT_TRACING_OPEN_TRACE_ERROR;
}
@ -448,6 +478,7 @@ namespace profiler {
m_bEnabled = true;
EASY_LOGMSG("Event tracing launched\n");
return EVENT_TRACING_LAUNCHED_SUCCESSFULLY;
}
@ -457,6 +488,8 @@ namespace profiler {
if (!m_bEnabled)
return;
EASY_LOGMSG("Event tracing is stopping...\n");
TRACING_END_TIME.store(getCurrentTime(), ::std::memory_order_release);
ControlTrace(m_openedHandle, KERNEL_LOGGER_NAME, props(), EVENT_TRACE_CONTROL_STOP);
@ -474,6 +507,8 @@ namespace profiler {
THREAD_PROCESS_INFO_TABLE[0U] = nullptr;
TRACING_END_TIME.store(~0ULL, ::std::memory_order_release);
EASY_LOGMSG("Event tracing stopped\n");
}
} // END of namespace profiler.

143
easy_profiler_core/profile_manager.cpp
View File

@ -47,6 +47,53 @@
#include "event_trace_win.h"
#include "current_time.h"
#if EASY_OPTION_LOG_ENABLED != 0
# include <iostream>
# ifndef EASY_ERRORLOG
# define EASY_ERRORLOG ::std::cerr
# endif
# ifndef EASY_LOG
# define EASY_LOG ::std::cerr
# endif
# ifndef EASY_ERROR
# define EASY_ERROR(LOG_MSG) EASY_ERRORLOG << "EasyProfiler ERROR: " << LOG_MSG
# endif
# ifndef EASY_WARNING
# define EASY_WARNING(LOG_MSG) EASY_ERRORLOG << "EasyProfiler WARNING: " << LOG_MSG
# endif
# ifndef EASY_LOGMSG
# define EASY_LOGMSG(LOG_MSG) EASY_LOG << "EasyProfiler INFO: " << LOG_MSG
# endif
# ifndef EASY_LOG_ONLY
# define EASY_LOG_ONLY(CODE) CODE
# endif
#else
# ifndef EASY_ERROR
# define EASY_ERROR(LOG_MSG)
# endif
# ifndef EASY_WARNING
# define EASY_WARNING(LOG_MSG)
# endif
# ifndef EASY_LOGMSG
# define EASY_LOGMSG(LOG_MSG)
# endif
# ifndef EASY_LOG_ONLY
# define EASY_LOG_ONLY(CODE)
# endif
#endif
#ifdef min
#undef min
#endif
@ -764,11 +811,13 @@ void ProfileManager::setEnabled(bool isEnable)
if (isEnable)
{
EASY_LOGMSG("Enabled profiling\n");
enableEventTracer();
m_beginTime = time;
}
else
{
EASY_LOGMSG("Disabled profiling\n");
disableEventTracer();
m_endTime = time;
}
@ -822,6 +871,8 @@ char ProfileManager::checkThreadExpired(ThreadStorage& _registeredThread)
uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bool _lockSpin)
{
EASY_LOGMSG("dumpBlocksToStream(_lockSpin = " << _lockSpin << ")...\n");
if (_lockSpin)
m_dumpSpin.lock();
@ -849,14 +900,36 @@ uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bo
std::this_thread::sleep_for(std::chrono::milliseconds(20));
// wait for all threads finish opened frames
EASY_LOG_ONLY(bool logged = false);
for (auto it = m_threads.begin(), end = m_threads.end(); it != end;)
{
if (!it->second.frame.load(std::memory_order_acquire))
{
++it;
EASY_LOG_ONLY(logged = false);
}
else
{
EASY_LOG_ONLY(
if (!logged)
{
logged = true;
if (it->second.named)
EASY_WARNING("Waiting for thread \"" << it->second.name << "\" finish opened frame (which is top EASY_BLOCK for this thread)...\n");
else
EASY_WARNING("Waiting for thread " << it->first << " finish opened frame (which is top EASY_BLOCK for this thread)...\n");
}
);
std::this_thread::sleep_for(std::chrono::milliseconds(10));
}
}
m_profilerStatus.store(EASY_PROF_DISABLED, std::memory_order_release);
EASY_LOGMSG("All threads have closed frames\n");
EASY_LOGMSG("Disabled profiling\n");
m_spin.lock();
m_storedSpin.lock();
// TODO: think about better solution because this one is not 100% safe...
@ -869,18 +942,31 @@ uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bo
{
// Read thread context switch events from temporary file
EASY_LOGMSG("Writing context switch events...\n");
uint64_t timestamp = 0;
uint32_t thread_from = 0, thread_to = 0;
std::ifstream infile(m_csInfoFilename.c_str());
if(infile.is_open()) {
if(infile.is_open())
{
EASY_LOG_ONLY(uint32_t num = 0);
std::string next_task_name;
pid_t process_to = 0;
while (infile >> timestamp >> thread_from >> thread_to >> next_task_name >> process_to) {
while (infile >> timestamp >> thread_from >> thread_to >> next_task_name >> process_to)
{
beginContextSwitch(thread_from, timestamp, thread_to, next_task_name.c_str(), false);
endContextSwitch(thread_to, (processid_t)process_to, timestamp, false);
EASY_LOG_ONLY(++num);
}
EASY_LOGMSG("Done, " << num << " context switch events wrote\n");
}
EASY_LOG_ONLY(
else {
EASY_ERROR("Can not open context switch log-file \"" << m_csInfoFilename << "\"\n");
}
)
}
#endif
@ -920,6 +1006,7 @@ uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bo
#else
#if !defined(USE_STD_CHRONO)
EASY_LOGMSG("Calculating CPU frequency\n");
double g_TicksPerNanoSec;
struct timespec begints, endts;
uint64_t begin = 0, end = 0;
@ -945,6 +1032,7 @@ uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bo
int64_t cpu_frequency = int(g_TicksPerNanoSec*1000000);
_outputStream.write(cpu_frequency*1000LL);
EASY_LOGMSG("Done calculating CPU frequency\n");
#else
_outputStream.write(0LL);
#endif
@ -1009,14 +1097,21 @@ uint32_t ProfileManager::dumpBlocksToStream(profiler::OStream& _outputStream, bo
if (_lockSpin)
m_dumpSpin.unlock();
EASY_LOGMSG("Done dumpBlocksToStream(). Dumped " << blocks_number << " blocks\n");
return blocks_number;
}
uint32_t ProfileManager::dumpBlocksToFile(const char* _filename)
{
EASY_LOGMSG("dumpBlocksToFile(\"" << _filename << "\")...\n");
std::ofstream outputFile(_filename, std::fstream::binary);
if (!outputFile.is_open())
{
EASY_ERROR("Can not open \"" << _filename << "\" for writing\n");
return 0;
}
profiler::OStream outputStream;
@ -1031,6 +1126,8 @@ uint32_t ProfileManager::dumpBlocksToFile(const char* _filename)
// Restore old outputStream buffer to avoid possible second memory free on stringstream destructor
s.rdbuf(oldbuf);
EASY_LOGMSG("Done dumpBlocksToFile()\n");
return blocksNumber;
}
@ -1092,16 +1189,18 @@ void ProfileManager::stopListen()
if (m_listenThread.joinable())
m_listenThread.join();
m_isAlreadyListening.store(false, std::memory_order_release);
EASY_LOGMSG("Listening stopped\n");
}
//////////////////////////////////////////////////////////////////////////
//#define EASY_DEBUG_NET_PRINT
void ProfileManager::listen(uint16_t _port)
{
EASY_THREAD_SCOPE("EasyProfiler.Listen");
EASY_LOGMSG("Listening started\n");
EasySocket socket;
profiler::net::Message replyMessage(profiler::net::MESSAGE_TYPE_REPLY_START_CAPTURING);
@ -1117,9 +1216,7 @@ void ProfileManager::listen(uint16_t _port)
EASY_EVENT("ClientConnected", EASY_COLOR_INTERNAL_EVENT, profiler::OFF);
hasConnect = true;
#ifdef EASY_DEBUG_NET_PRINT
printf("GUI-client connected\n");
#endif
EASY_LOGMSG("GUI-client connected\n");
// Send reply
{
@ -1155,16 +1252,13 @@ void ProfileManager::listen(uint16_t _port)
{
case profiler::net::MESSAGE_TYPE_CHECK_CONNECTION:
{
#ifdef EASY_DEBUG_NET_PRINT
printf("receive MESSAGE_TYPE_CHECK_CONNECTION\n");
#endif
EASY_LOGMSG("receive MESSAGE_TYPE_CHECK_CONNECTION\n");
break;
}
case profiler::net::MESSAGE_TYPE_REQUEST_START_CAPTURE:
{
#ifdef EASY_DEBUG_NET_PRINT
printf("receive REQUEST_START_CAPTURE\n");
#endif
EASY_LOGMSG("receive REQUEST_START_CAPTURE\n");
::profiler::timestamp_t t = 0;
EASY_FORCE_EVENT(t, "StartCapture", EASY_COLOR_START, profiler::OFF);
@ -1185,9 +1279,8 @@ void ProfileManager::listen(uint16_t _port)
case profiler::net::MESSAGE_TYPE_REQUEST_STOP_CAPTURE:
{
#ifdef EASY_DEBUG_NET_PRINT
printf("receive REQUEST_STOP_CAPTURE\n");
#endif
EASY_LOGMSG("receive REQUEST_STOP_CAPTURE\n");
m_dumpSpin.lock();
auto time = getCurrentTime();
const auto prev = m_profilerStatus.exchange(EASY_PROF_DUMP, std::memory_order_release);
@ -1234,9 +1327,7 @@ void ProfileManager::listen(uint16_t _port)
case profiler::net::MESSAGE_TYPE_REQUEST_BLOCKS_DESCRIPTION:
{
#ifdef EASY_DEBUG_NET_PRINT
printf("receive REQUEST_BLOCKS_DESCRIPTION\n");
#endif
EASY_LOGMSG("receive REQUEST_BLOCKS_DESCRIPTION\n");
profiler::OStream os;
@ -1288,9 +1379,7 @@ void ProfileManager::listen(uint16_t _port)
{
auto data = reinterpret_cast<const profiler::net::BlockStatusMessage*>(message);
#ifdef EASY_DEBUG_NET_PRINT
printf("receive EDIT_BLOCK_STATUS id=%u status=%u\n", data->id, data->status);
#endif
EASY_LOGMSG("receive EDIT_BLOCK_STATUS id=" << data->id << " status=" << data->status << std::endl);
setBlockStatus(data->id, static_cast<::profiler::EasyBlockStatus>(data->status));
@ -1301,9 +1390,7 @@ void ProfileManager::listen(uint16_t _port)
{
auto data = reinterpret_cast<const profiler::net::BoolMessage*>(message);
#ifdef EASY_DEBUG_NET_PRINT
printf("receive EVENT_TRACING_STATUS on=%d\n", data->flag ? 1 : 0);
#endif
EASY_LOGMSG("receive EVENT_TRACING_STATUS on=" << data->flag << std::endl);
m_isEventTracingEnabled.store(data->flag, std::memory_order_release);
break;
@ -1311,13 +1398,11 @@ void ProfileManager::listen(uint16_t _port)
case profiler::net::MESSAGE_TYPE_EVENT_TRACING_PRIORITY:
{
#if defined(_WIN32) || defined(EASY_DEBUG_NET_PRINT)
#if defined(_WIN32) || EASY_OPTION_LOG_ENABLED != 0
auto data = reinterpret_cast<const profiler::net::BoolMessage*>(message);
#endif
#ifdef EASY_DEBUG_NET_PRINT
printf("receive EVENT_TRACING_PRIORITY low=%d\n", data->flag ? 1 : 0);
#endif
EASY_LOGMSG("receive EVENT_TRACING_PRIORITY low=" << data->flag << std::endl);
#ifdef _WIN32
EasyEventTracer::instance().setLowPriority(data->flag);