前言
Redis源码中定义了几个和日志相关的函数,用于将不同级别的信息打印到不同的位置(日志文件或标准输出,取决于配置文件的设置),这些函数的定义位于 server.h 和server.c 文件中,包括:
void serverLog(int level, const char *fmt, ...);
void serverLogRaw(int level, const char *msg);
void serverLogFromHandler(int level, const char *msg);
其中, serverLogRaw() 是 serverLog() 的底层实现,差别在于 serverLog() 进行了上层的简单封装,以支持可视化字符串的打印,而 serverLogRaw() 则只接收完整的字符串进行打印。
Redis Logging定义了四种日志等级,从低到高分别为:调试、详细、注意、警告。对应的宏定义如下:
/* Log levels */
#define LL_DEBUG 0
#define LL_VERBOSE 1
#define LL_NOTICE 2
#define LL_WARNING 3
#define LL_RAW (1<<10) /* Modifier to log without timestamp */
serverLog()
serverLog() 函数提供了一个printf-alike的日志打印支持,能够支持格式化字符串,并接收可变参数。
void serverLog(int level, const char *fmt, ...) {
va_list ap;
char msg[LOG_MAX_LEN]; if ((level&0xff) < server.verbosity) return; va_start(ap, fmt);
vsnprintf(msg, sizeof(msg), fmt, ap);
va_end(ap); serverLogRaw(level,msg);
}
函数中对日志打印级别进行了控制,只有给定日志级别不小于服务器设置的级别时,日志才会打印出来,否则,函数提前返回。
利用了 va_list 、va_start 、va_end 等函数对可变参数进行了支持,其原理是利用函数参数在栈中的空间排布,栈空间排布和va_list 的操作如下图所示:
int vsnprintf (char * s, size_t n, const char * format, va_list arg) 函数利用可变参数列表来格式化字符串,把字符串保存在 s 指向的空间中。
serverLogRaw()
serverLogRaw()函数是日志打印的底层实现,主要控制了日志打印的如下几个方面:
- 日志级别。 如果给定级别低于服务器设置的server.verbosity 级别,日志不输出,函数直接返回。
- 日志打印位置。如果服务器配置了 server.logfile ,日志会打印到相应的日志文件中。否则,直接输出至标准输出。
- 日志打印格式。如果在日志级别中设置了原始位,则只打印原始字符串信息。否则,会在字符串首加入进程号、日期等信息。
void serverLogRaw(int level, const char *msg) {
// Defined in syslog.h
const int syslogLevelMap[] = { LOG_DEBUG, LOG_INFO, LOG_NOTICE, LOG_WARNING };
const char *c = ".-*#";
FILE *fp;
char buf[];
int rawmode = (level & LL_RAW);
int log_to_stdout = server.logfile[] == '\0'; level &= 0xff; /* clear flags */
if (level < server.verbosity) return; fp = log_to_stdout ? stdout : fopen(server.logfile,"a");
if (!fp) return; // log without timestamp
if (rawmode) {
fprintf(fp,"%s",msg);
} else {
int off;
struct timeval tv;
int role_char;
pid_t pid = getpid(); gettimeofday(&tv,NULL);
struct tm tm;
/*
* 自定义的localtime函数
* 标准的 localtime 在多线程下可能出现死锁的情况
*/
nolocks_localtime(&tm,tv.tv_sec,server.timezone,server.daylight_active);
off = strftime(buf,sizeof(buf),"%d %b %Y %H:%M:%S.",&tm);
snprintf(buf+off,sizeof(buf)-off,"%03d",(int)tv.tv_usec/);
if (server.sentinel_mode) {
role_char = 'X'; /* Sentinel. */
} else if (pid != server.pid) {
role_char = 'C'; /* RDB / AOF writing child. */
} else {
role_char = (server.masterhost ? 'S':'M'); /* Slave or Master. */
}
/*
* 依次存放:
* pid, X/C/S/M, time, .-*#, msg
*/
fprintf(fp,"%d:%c %s %c %s\n",
(int)getpid(),role_char, buf,c[level],msg);
}
fflush(fp); if (!log_to_stdout) fclose(fp);
if (server.syslog_enabled) syslog(syslogLevelMap[level], "%s", msg);
}
对于包含时间信息的日志打印会被加入如下信息在字符串首部:
- 服务器进程号
- X/C/S/M: 体现当前进程的状态,主进程 / 从进程 / Sentinel / RDB / AOF子进程
- 格式化后的日期
- 表示不同日志等级的字符
- 信息字符串
日志打印实例:
:C Sep ::35.518 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
:C Sep ::35.518 # Redis version=4.0., bits=, commit=, modified=, pid=, just started
:C Sep ::35.518 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
:M Sep ::35.519 # You requested maxclients of requiring at least max file descriptors.
:M Sep ::35.519 # Server can't set maximum open files to 10032 because of OS error: Invalid argument.
:M Sep ::35.519 # Current maximum open files is . maxclients has been reduced to to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'.
_._
_.-``__ ''-._
_.-`` `. `_. ''-._ Redis 4.0. (/) bit
.-`` .-```. ```\/ _.,_ ''-._
( ' , .-` | `, ) Running in standalone mode
|`-._`-...-` __...-.``-._|'` _.-'| Port:
| `-._ `._ / _.-' | PID: 2084
`-._ `-._ `-./ _.-' _.-'
|`-._`-._ `-.__.-' _.-'_.-'|
| `-._`-._ _.-'_.-' | http://redis.io
`-._ `-._`-.__.-'_.-' _.-'
|`-._`-._ `-.__.-' _.-'_.-'|
| `-._`-._ _.-'_.-' |
`-._ `-._`-.__.-'_.-' _.-'
`-._ `-.__.-' _.-'
`-._ _.-'
`-.__.-' :M Sep ::35.523 # WARNING: The TCP backlog setting of cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of .
:M Sep ::35.523 # Server initialized
:M Sep ::35.523 # WARNING overcommit_memory is set to ! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
:M Sep ::35.525 * DB loaded from disk: 0.002 seconds
:M Sep ::35.525 * Ready to accept connections
nolocks_localtime()
值得一提的是,在对时间进行转换时,Redis源码考虑到标准的 localtime() 在多线程下可能出现的死锁问题,所以自定义了一个不带锁的函数 nolocks_localtime() ,用于完成时间格式的转换。
关于 localtime() 函数多线程下可能带来的死锁问题,可以参考这篇博文的分析:https://juejin.im/post/6844903775539298318。
参考资料:
localtime函数的死锁风险 : https://juejin.im/post/6844903775539298318