Magic-Mirror/gecko-dev
1
0
Fork 0
mirror of https://github.com/mozilla/gecko-dev.git synced 2024-11-24 05:11:16 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Bug 1608523: Add MOZ_LOG_TIME() to allow time ranges for logs r=froydnj

Browse Source 
Differential Revision: https://phabricator.services.mozilla.com/D59552

--HG--
extra : moz-landing-system : lando
This commit is contained in:
Randell Jesup 2020-01-14 21:36:19 +00:00
parent 048ed6e9de
commit 639b7b7769
4 changed files with 99 additions and 11 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
netwerk/protocol/http/HttpLog.h
View File

@ -52,6 +52,8 @@ extern LazyLogModule gHttpLog;
#define LOG5(args) \
MOZ_LOG(mozilla::net::gHttpLog, mozilla::LogLevel::Verbose, args)
#define LOG(args) LOG4(args)
#define LOGTIME(start, args) \
MOZ_LOG_TIME(mozilla::net::gHttpLog, mozilla::LogLevel::Debug, &start, args)
#define LOG1_ENABLED() \
MOZ_LOG_TEST(mozilla::net::gHttpLog, mozilla::LogLevel::Error)

7
tools/profiler/public/ProfilerMarkerPayload.h
View File

@ -620,6 +620,13 @@ class LogMarkerPayload : public ProfilerMarkerPayload {
mModule(aModule),
mText(aText) {}
LogMarkerPayload(const char* aModule, const char* aText,
const mozilla::TimeStamp& aStartTime,
const mozilla::TimeStamp& aEndTime)
: ProfilerMarkerPayload(aStartTime, aEndTime),
mModule(aModule),
mText(aText) {}
DECL_STREAM_PAYLOAD
private:

74
xpcom/base/Logging.cpp
View File

@ -58,6 +58,14 @@ void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt,
va_end(ap);
}
void log_print(const LogModule* aModule, LogLevel aLevel, TimeStamp* aStart,
const char* aFmt, ...) {
va_list ap;
va_start(ap, aFmt);
aModule->Printv(aLevel, aStart, aFmt, ap);
va_end(ap);
}
} // namespace detail
LogLevel ToLogLevel(int32_t aLevel) {
@ -377,6 +385,11 @@ class LogModuleManager {
void Print(const char* aName, LogLevel aLevel, const char* aFmt,
va_list aArgs) MOZ_FORMAT_PRINTF(4, 0) {
Print(aName, aLevel, nullptr, aFmt, aArgs);
}
void Print(const char* aName, LogLevel aLevel, const TimeStamp* aStart,
const char* aFmt, va_list aArgs) MOZ_FORMAT_PRINTF(5, 0) {
long pid = static_cast<long>(base::GetCurrentProcId());
const size_t kBuffSize = 1024;
char buff[kBuffSize];
@ -406,8 +419,15 @@ class LogModuleManager {
#ifdef MOZ_GECKO_PROFILER
if (mAddProfilerMarker && profiler_can_accept_markers()) {
PROFILER_ADD_MARKER_WITH_PAYLOAD("LogMessages", OTHER, LogMarkerPayload,
(aName, buffToWrite, TimeStamp::Now()));
if (aStart) {
PROFILER_ADD_MARKER_WITH_PAYLOAD(
"LogMessages", OTHER, LogMarkerPayload,
(aName, buffToWrite, *aStart, TimeStamp::Now()));
} else {
PROFILER_ADD_MARKER_WITH_PAYLOAD(
"LogMessages", OTHER, LogMarkerPayload,
(aName, buffToWrite, TimeStamp::Now()));
}
}
#endif
@ -446,7 +466,7 @@ class LogModuleManager {
currentThreadName = noNameThread;
}
if (!mAddTimestamp) {
if (!mAddTimestamp && !aStart) {
if (!mIsRaw) {
fprintf_stderr(out, "[%s %ld: %s]: %s/%s %s%s",
nsDebugImpl::GetMultiprocessMode(), pid,
@ -456,14 +476,38 @@ class LogModuleManager {
fprintf_stderr(out, "%s%s", buffToWrite, newline);
}
} else {
PRExplodedTime now;
PR_ExplodeTime(PR_Now(), PR_GMTParameters, &now);
fprintf_stderr(
out,
"%04d-%02d-%02d %02d:%02d:%02d.%06d UTC - [%s %ld: %s]: %s/%s %s%s",
now.tm_year, now.tm_month + 1, now.tm_mday, now.tm_hour, now.tm_min,
now.tm_sec, now.tm_usec, nsDebugImpl::GetMultiprocessMode(), pid,
currentThreadName, ToLogStr(aLevel), aName, buffToWrite, newline);
if (aStart) {
// XXX is there a reasonable way to convert one to the other? this is
// bad
PRTime prnow = PR_Now();
TimeStamp tmnow = TimeStamp::NowUnfuzzed();
TimeDuration duration = tmnow - *aStart;
PRTime prstart = prnow - duration.ToMicroseconds();
PRExplodedTime now;
PRExplodedTime start;
PR_ExplodeTime(prnow, PR_GMTParameters, &now);
PR_ExplodeTime(prstart, PR_GMTParameters, &start);
// Ignore that the start time might be in a different day
fprintf_stderr(
out,
"%04d-%02d-%02d %02d:%02d:%02d.%06d -> %02d:%02d:%02d.%06d UTC "
"(%.1gms)- [%s %ld: %s]: %s/%s %s%s",
now.tm_year, now.tm_month + 1, start.tm_mday, start.tm_hour,
start.tm_min, start.tm_sec, start.tm_usec, now.tm_hour, now.tm_min,
now.tm_sec, now.tm_usec, duration.ToMilliseconds(),
nsDebugImpl::GetMultiprocessMode(), pid, currentThreadName,
ToLogStr(aLevel), aName, buffToWrite, newline);
} else {
PRExplodedTime now;
PR_ExplodeTime(PR_Now(), PR_GMTParameters, &now);
fprintf_stderr(
out,
"%04d-%02d-%02d %02d:%02d:%02d.%06d UTC - [%s %ld: %s]: %s/%s %s%s",
now.tm_year, now.tm_month + 1, now.tm_mday, now.tm_hour, now.tm_min,
now.tm_sec, now.tm_usec, nsDebugImpl::GetMultiprocessMode(), pid,
currentThreadName, ToLogStr(aLevel), aName, buffToWrite, newline);
}
}
if (mIsSync) {
@ -596,4 +640,12 @@ void LogModule::Printv(LogLevel aLevel, const char* aFmt, va_list aArgs) const {
sLogModuleManager->Print(Name(), aLevel, aFmt, aArgs);
}
void LogModule::Printv(LogLevel aLevel, const TimeStamp* aStart, const char* aFmt,
va_list aArgs) const {
MOZ_ASSERT(sLogModuleManager != nullptr);
// Forward to LogModule manager w/ level and name
sLogModuleManager->Print(Name(), aLevel, aStart, aFmt, aArgs);
}
} // namespace mozilla

27
xpcom/base/Logging.h
View File

@ -14,6 +14,7 @@
#include "mozilla/Atomics.h"
#include "mozilla/Attributes.h"
#include "mozilla/Likely.h"
#include "mozilla/TimeStamp.h"
// We normally have logging enabled everywhere, but measurements showed that
// having logging enabled on Android is quite expensive (hundreds of kilobytes
@ -136,6 +137,9 @@ class LogModule {
void Printv(LogLevel aLevel, const char* aFmt, va_list aArgs) const
MOZ_FORMAT_PRINTF(3, 0);
void Printv(LogLevel aLevel, const TimeStamp* aStart, const char* aFmt,
va_list aArgs) const MOZ_FORMAT_PRINTF(4, 0);
/**
* Retrieves the module name.
*/
@ -206,6 +210,9 @@ inline bool log_test(const LogModule* module, LogLevel level) {
void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt, ...)
MOZ_FORMAT_PRINTF(3, 4);
void log_print(const LogModule* aModule, LogLevel aLevel, TimeStamp* aStart,
const char* aFmt, ...) MOZ_FORMAT_PRINTF(4, 5);
} // namespace detail
} // namespace mozilla
@ -265,6 +272,11 @@ void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt, ...)
// MOZ_LOG even when logging is disabled to ensure the compiler sees that
// variables only used during logging code are actually used, even if the
// code will never be executed.) Hence, the following code.
//
// MOZ_LOG_DURATION takes a start time, and will generate a time range
// in the logs. Also, if 'profilermarkers' is used in the env var
// MOZ_LOG, MOZ_LOG_DURATION will generate a marker with a time
// duration instead of a single point in time.
#if MOZ_LOGGING_ENABLED
# define MOZ_LOG(_module, _level, _args) \
do { \
@ -274,6 +286,14 @@ void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt, ...)
MOZ_LOG_EXPAND_ARGS _args); \
} \
} while (0)
# define MOZ_LOG_DURATION(_module, _level, start, _args) \
do { \
const ::mozilla::LogModule* moz_real_module = _module; \
if (MOZ_LOG_TEST(moz_real_module, _level)) { \
mozilla::detail::log_print(moz_real_module, _level, start, \
MOZ_LOG_EXPAND_ARGS _args); \
} \
} while (0)
#else
# define MOZ_LOG(_module, _level, _args) \
do { \
@ -282,6 +302,13 @@ void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt, ...)
MOZ_LOG_EXPAND_ARGS _args); \
} \
} while (0)
# define MOZ_LOG_DURATION(_module, _level, start, _args) \
do { \
if (MOZ_LOG_TEST(_module, _level)) { \
mozilla::detail::log_print(_module, _level, start, \
MOZ_LOG_EXPAND_ARGS _args); \
} \
} while (0)
#endif
// This #define is a Logging.h-only knob! Don't encourage people to get fancy