Merge remote-tracking branch 'nccl/master' into develop
This commit is contained in:
BertanDogancay
+149
-14
@@ -6,6 +6,7 @@
|
||||
|
||||
#include "core.h"
|
||||
#include "nccl_net.h"
|
||||
#include <ctime>
|
||||
#include <stdlib.h>
|
||||
#include <stdarg.h>
|
||||
#include <stdio.h>
|
||||
@@ -16,6 +17,11 @@
|
||||
#include "param.h"
|
||||
|
||||
int ncclDebugLevel = -1;
|
||||
static uint32_t ncclDebugTimestampLevels = 0; // bitmaps of levels that have timestamps turned on
|
||||
static char ncclDebugTimestampFormat[256]; // with space for subseconds
|
||||
static int ncclDebugTimestampSubsecondsStart; // index where the subseconds starts
|
||||
static uint64_t ncclDebugTimestampMaxSubseconds; // Max number of subseconds plus 1, used in duration ratio
|
||||
static int ncclDebugTimestampSubsecondDigits; // Number of digits to display
|
||||
static int pid = -1;
|
||||
static char hostname[1024];
|
||||
thread_local int ncclDebugNoWarn = 0;
|
||||
@@ -114,6 +120,88 @@ static void ncclDebugInit() {
|
||||
ncclWarnSetDebugInfo = value;
|
||||
}
|
||||
|
||||
// Determine which debug levels will have timestamps.
|
||||
const char* timestamps = ncclGetEnv("NCCL_DEBUG_TIMESTAMP_LEVELS");
|
||||
if (timestamps == nullptr) {
|
||||
ncclDebugTimestampLevels = (1<<NCCL_LOG_WARN);
|
||||
} else {
|
||||
int invert = 0;
|
||||
if (timestamps[0] == '^') { invert = 1; ++timestamps; }
|
||||
ncclDebugTimestampLevels = invert ? ~0U : 0U;
|
||||
char *timestampsDup = strdup(timestamps);
|
||||
char *level = strtok(timestampsDup, ",");
|
||||
while (level != NULL) {
|
||||
uint32_t mask = 0;
|
||||
if (strcasecmp(level, "ALL") == 0) {
|
||||
mask = ~0U;
|
||||
} else if (strcasecmp(level, "VERSION") == 0) {
|
||||
mask = (1<<NCCL_LOG_VERSION);
|
||||
} else if (strcasecmp(level, "WARN") == 0) {
|
||||
mask = (1<<NCCL_LOG_WARN);
|
||||
} else if (strcasecmp(level, "INFO") == 0) {
|
||||
mask = (1<<NCCL_LOG_INFO);
|
||||
} else if (strcasecmp(level, "ABORT") == 0) {
|
||||
mask = (1<<NCCL_LOG_ABORT);
|
||||
} else if (strcasecmp(level, "TRACE") == 0) {
|
||||
mask = (1<<NCCL_LOG_TRACE);
|
||||
} else {
|
||||
// Silently fail.
|
||||
}
|
||||
if (mask) {
|
||||
if (invert) ncclDebugTimestampLevels &= ~mask;
|
||||
else ncclDebugTimestampLevels |= mask;
|
||||
}
|
||||
level = strtok(NULL, ",");
|
||||
}
|
||||
free(timestampsDup);
|
||||
}
|
||||
|
||||
// Store a copy of the timestamp format with space for the subseconds, if used.
|
||||
const char* tsFormat = ncclGetEnv("NCCL_DEBUG_TIMESTAMP_FORMAT");
|
||||
if (tsFormat == nullptr) tsFormat = "[%F %T] ";
|
||||
ncclDebugTimestampSubsecondsStart = -1;
|
||||
// Find where the subseconds are in the format.
|
||||
for (int i=0; tsFormat[i] != '\0'; ++i) {
|
||||
if (tsFormat[i]=='%' && tsFormat[i+1]=='%') { // Next two chars are "%"
|
||||
// Skip the next character, too, and restart checking after that.
|
||||
++i;
|
||||
continue;
|
||||
}
|
||||
if (tsFormat[i]=='%' && // Found a percentage
|
||||
('1' <= tsFormat[i+1] && tsFormat[i+1] <= '9') && // Next char is a digit between 1 and 9 inclusive
|
||||
tsFormat[i+2]=='f' // Two characters later is an "f"
|
||||
) {
|
||||
constexpr int replaceLen = sizeof("%Xf") - 1;
|
||||
ncclDebugTimestampSubsecondDigits = tsFormat[i+1] - '0';
|
||||
if (ncclDebugTimestampSubsecondDigits + strlen(tsFormat) - replaceLen > sizeof(ncclDebugTimestampFormat) - 1) {
|
||||
// Won't fit; fall back on the default.
|
||||
break;
|
||||
}
|
||||
ncclDebugTimestampSubsecondsStart = i;
|
||||
ncclDebugTimestampMaxSubseconds = 1;
|
||||
|
||||
memcpy(ncclDebugTimestampFormat, tsFormat, i);
|
||||
for (int j=0; j<ncclDebugTimestampSubsecondDigits; ++j) {
|
||||
ncclDebugTimestampFormat[i+j] = ' ';
|
||||
ncclDebugTimestampMaxSubseconds *= 10;
|
||||
}
|
||||
strcpy(ncclDebugTimestampFormat+i+ncclDebugTimestampSubsecondDigits, tsFormat+i+replaceLen);
|
||||
break;
|
||||
}
|
||||
}
|
||||
if (ncclDebugTimestampSubsecondsStart == -1) {
|
||||
if (strlen(tsFormat) < sizeof(ncclDebugTimestampFormat)) {
|
||||
strcpy(ncclDebugTimestampFormat, tsFormat);
|
||||
} else {
|
||||
strcpy(ncclDebugTimestampFormat, "[%F %T] ");
|
||||
}
|
||||
}
|
||||
|
||||
// Replace underscore with spaces... it is hard to put spaces in command line parameters.
|
||||
for (int i=0; ncclDebugTimestampFormat[i] != '\0'; ++i) {
|
||||
if (ncclDebugTimestampFormat[i]=='_') ncclDebugTimestampFormat[i] = ' ';
|
||||
}
|
||||
|
||||
// Cache pid and hostname
|
||||
getHostName(hostname, 1024, '.');
|
||||
pid = getpid();
|
||||
@@ -194,39 +282,86 @@ void ncclDebugLog(ncclDebugLogLevel level, unsigned long flags, const char *file
|
||||
tid = syscall(SYS_gettid);
|
||||
}
|
||||
|
||||
char buffer[1024];
|
||||
size_t len = 0;
|
||||
|
||||
// WARNs come with an extra newline at the beginning.
|
||||
if (level == NCCL_LOG_WARN) {
|
||||
buffer[len++] = '\n';
|
||||
};
|
||||
|
||||
// Add the timestamp to the buffer if they are turned on for this level.
|
||||
if (ncclDebugTimestampLevels & (1<<level)) {
|
||||
if (ncclDebugTimestampFormat[0] != '\0') {
|
||||
struct timespec ts;
|
||||
clock_gettime(CLOCK_REALTIME, &ts); // clock_gettime failure should never happen
|
||||
std::tm nowTm;
|
||||
localtime_r(&ts.tv_sec, &nowTm);
|
||||
|
||||
// Add the subseconds portion if it is part of the format.
|
||||
char localTimestampFormat[sizeof(ncclDebugTimestampFormat)];
|
||||
const char* pformat = ncclDebugTimestampFormat;
|
||||
if (ncclDebugTimestampSubsecondsStart != -1) {
|
||||
pformat = localTimestampFormat; // Need to use the local version which has subseconds
|
||||
memcpy(localTimestampFormat, ncclDebugTimestampFormat, ncclDebugTimestampSubsecondsStart);
|
||||
snprintf(localTimestampFormat + ncclDebugTimestampSubsecondsStart,
|
||||
ncclDebugTimestampSubsecondDigits+1,
|
||||
"%0*ld", ncclDebugTimestampSubsecondDigits,
|
||||
ts.tv_nsec / (1000000000UL/ncclDebugTimestampMaxSubseconds));
|
||||
strcpy( localTimestampFormat+ncclDebugTimestampSubsecondsStart+ncclDebugTimestampSubsecondDigits,
|
||||
ncclDebugTimestampFormat+ncclDebugTimestampSubsecondsStart+ncclDebugTimestampSubsecondDigits);
|
||||
}
|
||||
|
||||
// Format the time. If it runs out of space, fall back on a simpler format.
|
||||
int adv = std::strftime(buffer+len, sizeof(buffer)-len, pformat, &nowTm);
|
||||
if (adv==0 && ncclDebugTimestampFormat[0] != '\0') {
|
||||
// Ran out of space. Fall back on the default. This should never fail.
|
||||
adv = std::strftime(buffer+len, sizeof(buffer)-len, "[%F %T] ", &nowTm);
|
||||
}
|
||||
len += adv;
|
||||
}
|
||||
}
|
||||
len = std::min(len, sizeof(buffer)-1); // prevent overflows
|
||||
|
||||
// Add hostname, pid and tid portion of the log line.
|
||||
if (level != NCCL_LOG_VERSION) {
|
||||
len += snprintf(buffer+len, sizeof(buffer)-len, "%s:%d:%d ", hostname, pid, tid);
|
||||
len = std::min(len, sizeof(buffer)-1); // prevent overflows
|
||||
}
|
||||
|
||||
int cudaDev = 0;
|
||||
if (!(level == NCCL_LOG_TRACE && flags == NCCL_CALL)) {
|
||||
(void)cudaGetDevice(&cudaDev);
|
||||
}
|
||||
|
||||
char buffer[4096];
|
||||
size_t len = 0;
|
||||
// Add level specific formatting.
|
||||
if (level == NCCL_LOG_WARN) {
|
||||
len = snprintf(buffer, sizeof(buffer), "\n%s:%d:%d [%d] %s:%d NCCL WARN ",
|
||||
hostname, pid, tid, cudaDev, filefunc, line);
|
||||
len += snprintf(buffer+len, sizeof(buffer)-len, "[%d] %s:%d NCCL WARN ", cudaDev, filefunc, line);
|
||||
if (ncclWarnSetDebugInfo) ncclDebugLevel = NCCL_LOG_INFO;
|
||||
} else if (level == NCCL_LOG_INFO) {
|
||||
len = snprintf(buffer, sizeof(buffer), "%s:%d:%d [%d] NCCL INFO ", hostname, pid, tid, cudaDev);
|
||||
len += snprintf(buffer+len, sizeof(buffer)-len, "[%d] NCCL INFO ", cudaDev);
|
||||
} else if (level == NCCL_LOG_TRACE && flags == NCCL_CALL) {
|
||||
len = snprintf(buffer, sizeof(buffer), "%s:%d:%d NCCL CALL ", hostname, pid, tid);
|
||||
len += snprintf(buffer+len, sizeof(buffer)-len, "NCCL CALL ");
|
||||
} else if (level == NCCL_LOG_TRACE) {
|
||||
auto delta = std::chrono::steady_clock::now() - ncclEpoch;
|
||||
double timestamp = std::chrono::duration_cast<std::chrono::duration<double>>(delta).count()*1000;
|
||||
len = snprintf(buffer, sizeof(buffer), "%s:%d:%d [%d] %f %s:%d NCCL TRACE ",
|
||||
hostname, pid, tid, cudaDev, timestamp, filefunc, line);
|
||||
len += snprintf(buffer+len, sizeof(buffer)-len, "[%d] %f %s:%d NCCL TRACE ", cudaDev, timestamp, filefunc, line);
|
||||
}
|
||||
len = std::min(len, sizeof(buffer)-1); // prevent overflows
|
||||
|
||||
// Add the message as given by the call site.
|
||||
va_list vargs;
|
||||
va_start(vargs, fmt);
|
||||
len += vsnprintf(buffer+len, sizeof(buffer)-len, fmt, vargs);
|
||||
va_end(vargs);
|
||||
// vsnprintf may return len >= sizeof(buffer) in the case of a truncated output.
|
||||
// Rewind len so that we can replace the final \0 by \n
|
||||
if (len >= sizeof(buffer)) len = sizeof(buffer)-1;
|
||||
if (len) {
|
||||
buffer[len++] = '\n';
|
||||
fwrite(buffer, 1, len, ncclDebugFile);
|
||||
}
|
||||
// Rewind len so that we can replace the final \0 by "\n"
|
||||
len = std::min(len, sizeof(buffer)-1); // prevent overflows
|
||||
|
||||
// Add a newline and write it to the debug file. No terminating null is
|
||||
// necessary since we write bytes instead of the string.
|
||||
buffer[len++] = '\n';
|
||||
fwrite(buffer, 1, len, ncclDebugFile);
|
||||
}
|
||||
|
||||
NCCL_API(void, ncclResetDebugInit);
|
||||
|
||||
Reference in New Issue
Block a user