总结一次C++ 程序优化历程

近期用到了一位师兄写的C++程序，总体功能良好。使用不同的数据测试，发现了一个明显的缺点：大数据量下，预处理过程耗时很长。中科院的某计算集群，普通队列中的程序运行时间不能超过6个小时。而手上这套程序，大数据量下预处理就花了不止六个小时，结果当然是还没开始就被结束了。

和天河二号的工作人员联系，确认没有执行时间限制。于是开通了天河二号的账号，把程序扔上去跑。执行大数据量时，程序莫名被kill。询问技术支持，得知是内存耗尽，建议每个节点的进程数少一点。如此折腾了两次，大数据量的例子没跑通，大部分时间都费在预处理上，然后程序崩了，又要调整参数重新再来。

耗时长，最多是多花点机时，问题不大。但是没跑通的情况下每次要等五六个小时，然后才知道能否运行，测试然后反馈的过程太低效。忍无可忍，就开始进行优化吧！

第一步，找出耗时的点。原来的程序输出日志用的cout，没有附带时间，不能通过日志发现耗时的点。为了找出性能关键点，第一步是改进log，在输出中加上时间。写了一个Log类，替换掉cout，程序的输出中就带上时间了：

#include "../include/Log.hpp"

#include 
#include 
#include 
#include 

using namespace std;

namespace tlanyan {

 string Log::datetimeFormat = "%F %T";

 Log::Log()
 {
 }

 void Log::info(const char* message) {
  cout << getCurrentTime() << " [info] " << message << endl;
 }

 void Log::debug(const char* message) {
#if DEBUG
  cout << getCurrentTime() << " [debug] " << message;
#endif;
 }

 const char* Log::getCurrentTime()
 {
  //locale::global(locale("zh_CN.utf8"));
  time_t t = time(NULL);
  char mbstr[512];
  if (strftime(mbstr, sizeof(mbstr), Log::datetimeFormat.c_str(), localtime(&t))) {
   return mbstr;
  }
  
  cerr << "获取或格式化时间错误!" << endl;

  exit(1);
 }

 Log::~Log()
 {
 }
}

// 调用示例：
Log::info("program begins...");

通过查看Log，定位到了耗时长的过程。

• 第一步，目测程序源代码，找出问题所在。该段代码比较好理解，主要是进行数据初始化和打标签。程序中规中矩，都是操控内存中的数组，没有磁盘、网络、进程通信等耗时调用。审查代码中发现第一个问题：内存重分配。程序声明了vector，没有指定大小，后续代码中使用push_back对数组的每一项进行赋值。内存分配和数据拷贝的代价是很大的，这应该是一个性能点。修改代码，声明时指定数组大小。编译并运行程序，结果表明省下了30%的耗时。
• 第二步，统计代码的工作量。耗时过程的初始化数据量，大概是整个数据量的10%，就算其中内嵌了两层循环，也不应该耗时如此多。为了查看是否有额外工作量，加入了计数器。运行结果显示，该段函数的计算量不大，耗时长应该有其他的原因。
• 第三步，根据经验判断是缓存失效导致。第一反应是用valgrind查看缓存命中，但valgrind模拟运行的效率太差，几个小时后kill掉放弃了。目测程序源码，发现很多数据都是从全局内存读取，没有充分利用缓存。修改代码，使用局部变量缓存全局数据，接下来代码中的数据使用缓存数据。经过测试，效果非常明显，提升了50%的效率。
• 第四步，查找其他性能热点。经过几次小的调优测试，发现一些全局内存访问不可避免（随机访问，无法利用缓存），按照目前的方式难以继续优化。要大幅降低耗时需要重写算法，目前无法保证对算法和程序意图十分了解，遂暂时作罢。

优化前后的结果对比：中等数据规模下，耗时从8'43"降到3'25"；大数据量下，耗时从4h38'44"降到1h49'21"（注：使用自己的机器测试，CPU主频3.46GHz，比中科院和天河二号集群的CPU主频都要高，所以耗时短）。从数据看出，效果还是很明显的。