先说下背景

前段时间的互联头公司头条非阿里云莫属了，时隔一年再现大规模故障，各大网友纷纷吃瓜，热度依旧居高不下。可是别人家的瓜没吃多久，热度还没冷却下来，我们线上也发生故障了。据报道此次阿里云的故障与某个底层组件有关，可以理解为单个组件的异常引发了整个系统的瘫痪。我们此次故障虽然没有导致整个系统瘫痪，但归咎其原因，也和阿里云的故障原因有点类似，也是由于单个公共组件库的异常导致的故障。具体原因是：监控平台服务端发布版本，刚好该版本有bug 导致监控 SDK 出现异常狂刷日志，结果就是各大业务服务（业务服务接入了该监控SDK）打印了大量的日志，最终因为打印日志导致了整体请求耗时上涨，很多服务耗时上涨了好几倍，从而超时率也跟着上涨了很多。

经排查，发现监控SDK的日志打印使用了 “LOG(ERROR) ” 代码进行了日志打印，这是 c++ glog 日志组件，使用了 LOG(ERROR) 进行日志打印，实际上是使用了glog 默认的同步的日志打印方式。这种方式除了是同步 write 操作，还同时打印到 xxxServer.ERROR、xxxServer.WARNING、xxxServer.INFO 三个日志文件，一次三份，而且狂刷每秒几万条的日志打印，可想而知，磁盘I/O怎么扛得住。

按常理，一个监控SDK的异常，最多影响上报数据丢失而已，但终究影响到了业务服务的性能，所以这就需要考虑到设计的合理性了。

业务服务架构

一般的业务服务架构如下图所示，业务逻辑层主要实现了对业务的处理，第三方依赖库层就是各种第三方组件库和SDK了。

一般我们要开发一个业务服务，业务逻辑都是自己手撕代码，但是像日志输出、监控、rpc框架等这些基础功能组件，肯定不用自己从头开发，现成的成熟稳定的组件拿过来用就好。当然,会涉及到一个选型的过程，比如日志组件库选型，开源的日志库也一抓一大把，选择哪个比较好？假如我们最终选择了spdlog日志库。

那么问题来了，业务服务依赖了监控SDK，监控SDK自身又依赖了glog日志库进行日志打印。这样会导致一个业务服务实际上显示和隐式地依赖了多个日志库，这样是否合理？显然这是不合理的。

说到这里，笔者觉得有两个问题值得探讨：

公共组件库需不需要打印日志？
如果需要打印，怎么打印比较合适？

公共组件库该不该打印日志

我们就拿监控 SDK 作为例子进行分析。一般情况下，业务服务逻辑处理过程中，或者处理完之后，会主动调用监控 SDK 的对外写入接口进行监控指标数据上报。如下图，蓝色箭头部分都是在请求处理流程中，也就是说无论哪一个环节出现阻塞都会影响整体请求耗时。

本次故障的主要原因就是监控SDK的写入接口这里的日志打印导致整体请求耗时上涨，从而超时率增加。当然日志打印只是其中一种可能导致阻塞的因素，在进行接口设计的时候，就要充分考虑到各种可能导致阻塞的因素，又比如异步队列，也是为了避免同步调用上报数据接口导致的阻塞而设计的。

所以，结论是什么？结论就是像上图中灰色箭头的流程，属于异步交互的、不影响请求处理流程的，可以适当打印一些日志，或者处理其他可能导致性能下降一点的操作。但是像上图中蓝色箭头部分，会影响请求处理流程的，建议只返回错误码，不打印日志，也不处理一些可能导致性能下降的操作。

公共库如何优雅地打印日志

前面说到，业务服务可能显示和隐式地使用了多个不同的日志库，业务服务的团队选择了 spdlog，而监控SDK的团队使用的是 glog。对于业务服务的团队来说，他们只是引入了监控 SDK，对于监控 SDK 使用了glog 是透明的，可能不清楚这个事情。可能还是这样一种情况：业务服务团队发现了 glog 的性能问题，或者其他缺陷，所以放弃了 glog，升级到了 spdlog，结果监控 SDK 又给带回来了，是不是用 “懵B“ 已经无法形容当时的心态，用 ”崩溃“ 也不足为过了。

有没有比较好的办法解决呢？当然有的。前面有介绍过『第三方依赖库中如何优雅地实现日志打印？』，其实使用的就是里面的方法。

具体的思想是：把打印日志的实现方式交给上层服务（业务服务），通过注入的方式把实现方式传递给监控 SDK。

如下图，监控 SDK 定义自己的日志打印抽象接口，以及一个日志打印的实例，该实例是按照抽象接口标准实现的日志打印方法。该实例可以指向一个默认的日志打印方法，比如输出的终端控制台。

如果上层有新的『日志打印方法实现』注入，那么将日志打印的实例指向该注入实例，这样日志打印的时候就使用到了上层的实现实例进行打印，上层实现的实例决定将日志输出到哪里（磁盘、远端日志中心等）。

如何实现

抽象接口

监控 SDK 先定义一个抽象接口。

class Logger {
public:
  //位置信息
  struct Location {
    Location(const char* file, int line)
      : file_(file), line_(line) {}
    const char* file_ = nullptr;
    int line_ = 0;
  };
  Logger(SEVERITY severity): severity_(severity) {}
  virtual ~Logger() {}
  //日志级别Set & Get
  virtual SEVERITY GetSeverity() { return severity_; }
  virtual void SetSeveriy(SEVERITY severity) { severity_ =  severity; }
  //各个严重级别的日志打印接口
  virtual void Trace(Location& loc, const char* message) = 0;
  virtual void Debug(Location& loc, const char* message) = 0;
  virtual void Info(Location& loc, const char* message) = 0;
  virtual void Warning(Location& loc, const char* message) = 0;
  virtual void Error(Location& loc, const char* message) = 0;
  virtual void Fatal(Location& loc, const char* message) = 0;
  virtual void Off(Location& loc, const char* message) = 0;
private:
  SEVERITY severity_;
};

在监控SDK中。

日志打印实例

std::shared_ptr<Logger> logger_;

在监控SDK中。

上层 ”注入“ 方法：

void SetLogger(std::shared_ptr<Logger>& logger) {
  logger_ = logger;
}

在监控SDK中。

监控 SDK 内部获取日志打印实例：

std::shared_ptr<Logger> GetLogger() {
  return logger_;
}

在监控SDK中。

监控 SDK 内部打印日志：

GetLogger()->Info(Logger::Location(__FILE__, __LINE__), "hello world!");

在监控SDK中。

更优雅一点的实现方式:

#define COMMON_LOG_TRACE(message) \
   GetLogger()->Trace(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG_DEBUG(message) \
   GetLogger()->Debug(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG_INFO(message) \
   GetLogger()->Info(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG_WARN(message) \
   GetLogger()->Warning(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG_ERROR(message) \
   GetLogger()->ERROR(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG_FATAL(message) \
   GetLogger()->Fatal(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG_OFF(message) \
   GetLogger()->Off(Logger::Location(__FILE__, __LINE__), message);
#define COMMON_LOG(severity, message) COMMON_LOG_ ## severity(message);

//使用方法
COMMON_LOG(INFO, "hello world");

在监控SDK中。

遵循接口标准的日志打印实现

使用 spdlog 输出日志。

class MyLogger: public Logger {
public:
  MyLogger(cmlg::SEVERITY severity): cmlg::Logger(severity) {}
  virtual void Trace(Location& loc, const char* message) override {
    spdlog::trace("[%s:%d] %s", loc.file_, loc.line_, message);
  }
  virtual void Debug(Location& loc, const char* message) override {
    spdlog::debug("[%s:%d] %s", loc.file_, loc.line_, message);
  }
  virtual void Info(Location& loc, const char* message) override {
    spdlog::info("[%s:%d] %s", loc.file_, loc.line_, message);
  }
  virtual void Warning(Location& loc, const char* message) override {
    spdlog::warn("[%s:%d] %s", loc.file_, loc.line_, message);
  }
  virtual void Error(Location& loc, const char* message) override {
    spdlog::error("[%s:%d] %s", loc.file_, loc.line_, message);
  }
  virtual void Fatal(Location& loc, const char* message) override {
    spdlog::critical("[%s:%d] %s", loc.file_, loc.line_, message);
  }
  virtual void Off(Location& loc, const char* message) override {
    spdlog::critical("[%s:%d] %s", loc.file_, loc.line_, message);
  }
};

在业务服务中。

如果想直接打印到终端怎么办？

class MyLogger: public Logger {
  public:
    MyLogger(cmlg::SEVERITY severity): cmlg::Logger(severity) {}
    ...
    virtual void Info(Location& loc, const char* message) override {
      std::cout << "[INFO][" << loc.file_ << ":" << loc.line_ << "] " << message << std::endl;
    }
    ...
};

在业务服务中。

还可以更优雅一点

有人会说以下 ”COMMON_LOG“ 这种实现方式，其 message 需要自己格式化，并不友好，而且如果配置的 Severity 是 ERROR 级别，Trace 这里虽然不会最终输出，但是也进行了 message 的格式化，实际也消耗了性能。

是的，确实会存在这样的问题，以上大体思想是没错的，但是我们可能优化一些，这里可以实现得更好。

COMMON_LOG(INFO, "hello world");

我们看看怎么实现成一下打印方式?

COMMON_LOG(INFO) << "hello world: " << name;

关键技术 std::ostream

关键技术是 std::ostream，其实现了 ” <<“ 流输入的方式。

先实现一个 LogStream 类如下：

class LogStream : public std::ostream {
  public:
    LogStream(char *buf, int len, int64_t ctr)
        : std::ostream(NULL),
          streambuf_(buf, len),
          ctr_(ctr),
          self_(this) {
      rdbuf(&streambuf_);
    }
    int64_t ctr() const { return ctr_; }
    void set_ctr(int64_t ctr) { ctr_ = ctr; }
    LogStream* self() const { return self_; }
    size_t pcount() const { return streambuf_.pcount(); }
    char* pbase() const { return streambuf_.pbase(); }
    char* str() const { return pbase(); }
  private:
    LogStream(const LogStream&);
    LogStream& operator=(const LogStream&);
    LogStreamBuf streambuf_;
    int64_t ctr_ = 0;
    LogStream *self_ = nullptr;
};
// LogStreamBuf 实现如下
class LogStreamBuf : public std::streambuf {
 public:
  LogStreamBuf(char *buf, int len) { setp(buf, buf + len - 2); }
  int_type overflow(int_type ch) { return ch; }
  size_t pcount() const { return static_cast<size_t>(pptr() - pbase()); }
  char* pbase() const { return std::streambuf::pbase(); }
};

日志消息体

再实现一个日志消息体 LogMessage 类如下：

class LogMessage {
  public:
    static const int kMaxLogMessageLen = 30000; //日志长度限制
    LogMessage(const char *file, int line, SEVERITY severity)
      : loc_(file, line), severity_(severity)
      , stream_(message_text_, kMaxLogMessageLen, 0) {}
    std::ostream& stream() { return stream_; }
    ~LogMessage() { flush(); }
  private:
    void flush();
  private:
    Logger::Location loc_;
    SEVERITY severity_;
    char message_text_[kMaxLogMessageLen+1] = {0};
    LogStream stream_;
};

定义一个实例吧。

class Global {
  public:
    static Global& Instance() {
      static Global glb;
      return glb;
    }
    Global() {}
    void SetLogger(std::shared_ptr<Logger> logger) { logger_ = logger; }
    std::shared_ptr<Logger> GetLogger() { assert(logger_); return logger_; }
  private:
    SEVERITY severity_ = SEVERITY_OFF;
    std::shared_ptr<Logger> logger_;
};
#define SET_COMMON_LOGGER(logger)  \
  Global::Instance().SetLogger(logger)
#define GET_COMMON_LOGGER() \
  Global::Instance().GetLogger()

怎么打印日志？

LogMessage(__FILE__, __LINE__, SEVERITY_INFO).stream() << "hello " << "world";

但是还是会有同样的问题，如果配置的 Severity 是ERROR，上面的日志也进行了日志消息格式化了，也就是说也消耗了性能了，本来期望如果传入 severity 小于 ERROR，就什么也不做，既不进行消息格式化，也不进行日志输出，但是这里没有达到这个效果。以下这样呢？

#define COMMON_LOG(severity) \
  !GET_COMMON_LOGGER()->GetSeverity() <= cmlg::SEVERITY_ ## severity? 
  (void) 0 : //当前severity 要大于等于配置的severity 才能打印，不然什么都不做
  LogMessage(__FILE__, __LINE__, cmlg::SEVERITY_ ## severity).stream() //此时进行日志消息体的格式化和输出

看起来可以满足需求了，但是还有一个问题，导致以上代码是不能编译通过的。.stream() 返回的是 std::ostream，和 (void) 0 的返回值不一样，所以编译不通过。那怎么样才能让后者也返回 void 呢？

此时 LogMessageVoidify 可以登场了，他的作用是将 & 后面的std::ostream 类型变量作为输入，然后什么也没做就返回 void。

class LogMessageVoidify {
  public:
    LogMessageVoidify() {}
    void operator&(std::ostream&) {}
};

如下代码所示，是不是就可以满足需求了？

#define COMMON_LOG(severity) \
  !GET_COMMON_LOGGER()->GetSeverity() <= cmlg::SEVERITY_ ## severity? 
  (void) 0 : //当前severity 要大于等于配置的severity 才能打印，不然什么都不做
  LogMessageVoidify() & LogMessage(__FILE__, __LINE__, cmlg::SEVERITY_ ## severity).stream() //此时进行日志消息体的格式化和输出

进一步将宏展开：

!GET_COMMON_LOGGER()->GetSeverity() <= cmlg::SEVERITY_ ## severity? 
(void) 0 :
LogMessageVoidify() & LogMessage(__FILE__, __LINE__, cmlg::SEVERITY_ ## severity).stream() << "hello " << "world";

看明白了吗？如果不满足 severity 就直接 (void) 0，什么也没做；否则，得做些什么。因为 << 优先级比 & 高，所以优先执行消息体的格式化，然后返回 std::ostream 类型变量。 LogMessageVoidify() & ostream_variable 实际上就是 LogMessageVoidify().operator&(ostream_variable)，其返回值是 void。

OK，大功告成，可以使用了。这里代码有点粗糙，详细代码请见：github.com/sullivan120… 。

小结一下

从一次公共库日志打印引起的故障出发，引发了两个思考：

公共组件库需不需要打印日志？
如果需要打印，怎么打印比较合适？

然后着重介绍了『2』中的优雅的实现方法，前半部分介绍了使用注入的方式保持日志落地方式统一，后半部分主要是以 std::stream ”流“ 的日志打印方式为主线介绍了如何更加优雅地实现日志打印方法。

最后，欢迎沟通和交流。

你能相信，一个公共库的日志打印居然引发了大面积故障?

先说下背景

业务服务架构

公共组件库该不该打印日志

公共库如何优雅地打印日志

如何实现

抽象接口

日志打印实例

遵循接口标准的日志打印实现

还可以更优雅一点

关键技术 std::ostream

日志消息体

小结一下