Measure time in C++ OpenMP code

引言

最近在利用openMP优化串行程序，将串行程序并行化，这就涉及到并行化后的效果的测量问题，很重要的一个指标就是程序执行时间。

在查阅了相当的资料后发现，很多OpenMP初学者都遇到过使用openMP做并行优化但测量时间并未提升，其实很多时候不是程序本身的bug，或许是工具的bug（血泪的教训呀QAQ）

说一说我遇到的坑。。。 不，你不想说。

昨天老板丢给我一个程序，让我用多线程优化下，我思索了一下决定用openMP试试。一开始使用C++函数库中自带的 clock () 函数，测量原程序中的loop函数的运行时间，结果进行openMP改写后时间并没有减少反而升高了，令我一度怀疑是并行出了问题，花了一下午时间研究openMP并行化，却没成想是测量工具的问题QAQ，后来改成了为了omp_get_wtime()效果明显，实验完成。为了以后少走弯路，在此记录一下。

Measure time in C++ OpenMP code

测量时间的工具有很多，我使用了c++中最简单的clock()函数与OpenMP中的omp_get_wtime()，下面先介绍二者，再进行下对比。

clock（）

clock_t clock (void);
Returns the processor time consumed by the program.
The value returned is expressed in clock ticks, which are units of time of a constant but system-specific length (with a relation of CLOCKS_PER_SEC clock ticks per second).

官方文档给出的解释是clock()返回程序的处理器时间，也就是CPU时间。但是这个时间是以系统时钟周期形式返回的，需要除以一个每秒时钟周期数CLOCKS_PER_SEC才能转换为我们所说的real time。

示例代码如下：

#include <time.h>
.....
int main()
{
	clock_t timeStart , timeEnd;
	double processingTime;
	timeStart = clock();
  	for(...)
  	.
  	.
  	timeEnd = clock();
	processingTime = (double) (timeEnd - timeStart) / CLOCKS_PER_SEC;
	return 0;
 }

参考文献：http://www.cplusplus.com/reference/ctime/clock/

omp_get_wtime()

double omp_get_wtime(void);
Returns the elapsed wall clock time in seconds.
The time is measured per thread, no guarantee can be made that two distinct threads measure the same time. Time is measured from some “time in the past”, which is an arbitrary time guaranteed not to change during the execution of the program.

官方文档给出的解释是omp_get_wtime()返回的是在程序执行过程中，从过去的任意一个固定时间点开始所经过的时间，单位秒。

示例代码如下：

#include <time.h>
.....
int main()
{
    	double timeStart, timeEnd;  
    	double elapsedTime;
    	timeStart= omp_get_wtime();  
    	for(...)
    	.
    	.
    	timeEnd= omp_get_wtime();  
    	elapsedTime = timeEnd - timeStart; 
    	return 0;
}

参考文献：https://gcc.gnu.org/onlinedocs/libgomp/omp_005fget_005fwtime.html

二者区别

在查阅了相当的资料后发现，很多人都遇到过这个问题，在此总结一下。

第一个区别

clock()函数测量的是CPU时间，是实实在在CPU运行所花费的时间，对于多核CPU而言，CPU时间是将所有CPU上运行的线程的时间累加得到的。

OMP函数omp_get_wtime()测量的是程序执行所经过的时间，是从一个时间点到另一个时间点所经历的时间。

第二个区别

clock()函数测量的是CPU时间，CPU时间就只包含CPU在某个任务上的实际处理时间，不包含运行时的等待系统资源等等相关延迟。

OMP函数omp_get_wtime()测量的是wall time，包含了运行时的所有延迟因素，是从更宏观的层面上来计算的程序实际执行时间。

参考文献：https://en.wikipedia.org/wiki/Elapsed_real_time

实验教训

随手写个demo测试一下：

#include <stdio.h>
#include <unistd.h>
#include <omp.h>
#include <math.h>
#include <time.h>

int main()
{
        clock_t clock_timer;
        double wall_timer;
        double c[10000];
        for (int nthreads = 1; nthreads <= omp_get_max_threads() - 1; ++nthreads)
        {
                clock_timer = clock();
                wall_timer = omp_get_wtime();
                printf("threads: %d ", nthreads);
                #pragma omp parallel num_threads(nthreads)
                for (int i = 0; i < 10000; i++)
                {
                        for (int j = 0; j < 10000; j++)
                                c[i] = sqrt(i * 4 + j * 2 + j);
                }
                printf("time on clock(): %13.8f s\t", (double) (clock() - clock_timer) / CLOCKS_PER_SEC);
                printf("time on wall: %13.8f s\n", omp_get_wtime()-wall_timer);
        }
        
                return 0;
}

用了一个二重loop，目的是为了扩大循环次数放大时间，以便更好观察结果。

实验环境：测试服务器一共2个8核cpu，共16核，测试1-15个线程下的CPU时间与omp wall-clock时间。
测试结果如下：

threads: 1 time on clock():    1.18000000 s time on wall:    1.18664212 s
threads: 2 time on clock():    2.38000000 s time on wall:    1.18867239 s
threads: 3 time on clock():    3.58000000 s time on wall:    1.19807996 s
threads: 4 time on clock():    4.80000000 s time on wall:    1.20108688 s
threads: 5 time on clock():    6.11000000 s time on wall:    1.22768376 s
threads: 6 time on clock():    7.30000000 s time on wall:    1.23721435 s
threads: 7 time on clock():    8.56000000 s time on wall:    1.23622449 s
threads: 8 time on clock():    9.98000000 s time on wall:    1.26976412 s
threads: 9 time on clock():   11.14000000 s time on wall:    1.27234287 s
threads: 10 time on clock():   12.45000000 s time on wall:    1.33065647 s
threads: 11 time on clock():   13.83000000 s time on wall:    1.35075363 s
threads: 12 time on clock():   15.01000000 s time on wall:    1.27852163 s
threads: 13 time on clock():   16.06000000 s time on wall:    1.25557764 s
threads: 14 time on clock():   17.45000000 s time on wall:    1.27296767 s
threads: 15 time on clock():   19.08000000 s time on wall:    1.35811380 s

可以看到clock()与omp_get_wtime()的区别了吧~~

很久都没更博，以后会多抽出点时间写写，希望能帮到大家o(￣▽￣)ブ
大家一起共同学习哦~~