Linux環境で現在時刻を取得したり、処理時間を測定したりするために使用するclock_gettime()関数について確認したのでまとめました。
clock_gettime()関数
# include <time.h>
int clock_gettime(clockid_t clk_id, struct timespec *tp);
struct timespec {
__kernel_time_t tv_sec; /* seconds */
long tv_nsec; /* nanoseconds */
};
clk_idに指定したクロック種別に従った時間情報を取得できます。
クロック種別として主なのを抜粋。
-
CLOCK_REALTIME
実時間。システムの時刻変更に影響を受ける。 -
CLOCK_MONOTONIC
ある開始時点からの経過時間。システムの時刻変更の影響は受けない。
開始時点は厳密には規定されていないが、大体は電源が入ってからの経過時間。 -
CLOCK_BOOTTIME
CLOCK_MONOTONICと同様だが、サスペンドしてしている時間も含まれる。 -
CLOCK_PROCESS_CPUTIME_ID
自プロセスが消費したCPU時間(各スレッドが消費したCPU時間の合計値) -
CLOCK_THREAD_CPUTIME_ID
自スレッドが消費したCPU時間
サンプルコード
それぞれどんな時間情報が実際に出力されるのかソースコードを作成。
以下にソースコードと実行例を載せます。
マルチスレッドで処理を行った際にそれぞれの処理開始時刻、処理終了時刻と、その経過時刻（差分）を確認しています。
# include <stdio.h>
# include <stdlib.h>
# include <pthread.h>
# include <unistd.h>
# include <sys/times.h>
static pthread_mutex_t g_mutex = PTHREAD_MUTEX_INITIALIZER;
//----------------------------------------------------------
// 時刻関連
//----------------------------------------------------------
// timespec差分算出関数
inline void sub_timespec(struct timespec* res, const struct timespec* a, const struct timespec* b)
{
if (a->tv_nsec >= b->tv_nsec) {
res->tv_nsec = a->tv_nsec - b->tv_nsec;
res->tv_sec = a->tv_sec - b->tv_sec;
} else {
res->tv_nsec = 1000000000 + a->tv_nsec - b->tv_nsec;
res->tv_sec = a->tv_sec - b->tv_sec - 1;
}
}
// 時刻ログクラス
class TimeLog
{
private:
struct timespec real;
struct timespec mono;
struct timespec boot;
struct timespec pcpu;
struct timespec tcpu;
public:
// 現在時刻の取得
TimeLog& getTime() {
clock_gettime(CLOCK_REALTIME, &real);
clock_gettime(CLOCK_MONOTONIC, &mono);
clock_gettime(CLOCK_BOOTTIME , &boot);
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &pcpu);
clock_gettime(CLOCK_THREAD_CPUTIME_ID , &tcpu);
return *this;
}
// 経過時間の設定
TimeLog& setElapsedTime(const TimeLog& start, const TimeLog& end) {
sub_timespec(&real, &end.real, &start.real);
sub_timespec(&mono, &end.mono, &start.mono);
sub_timespec(&boot, &end.boot, &start.boot);
sub_timespec(&pcpu, &end.pcpu, &start.pcpu);
sub_timespec(&tcpu, &end.tcpu, &start.tcpu);
return *this;
}
// ログ出力
TimeLog& printLog(const char* label) {
pthread_mutex_lock(&g_mutex);
printf("%16s", label);
printf(": real=%ld.%09ld", real.tv_sec, real.tv_nsec);
printf(", mono=%ld.%09ld", mono.tv_sec, mono.tv_nsec);
printf(", boot=%ld.%09ld", boot.tv_sec, boot.tv_nsec);
printf(", pcpu=%ld.%09ld", pcpu.tv_sec, pcpu.tv_nsec);
printf(", tcpu=%ld.%09ld", tcpu.tv_sec, tcpu.tv_nsec);
printf("\n");
pthread_mutex_unlock(&g_mutex);
return *this;
}
};
//----------------------------------------------------------
TimeLog elapsed_main;
TimeLog elapsed_A;
TimeLog elapsed_B;
TimeLog elapsed_C;
// 普通の処理
void* thread_A(void* param)
{
TimeLog start = TimeLog().getTime().printLog("Thread_A START");
for (int64_t ans = 0, i = 0; i <= 1000000000; i++) ans += i;
TimeLog end = TimeLog().getTime().printLog("Thread_A END ");
elapsed_A.setElapsedTime(start, end);
}
// 重めの処理
void* thread_B(void* param)
{
TimeLog start = TimeLog().getTime().printLog("Thread_B START");
for (int64_t ans = 0, i = 0; i <= 2000000000; i++) ans += i;
TimeLog end = TimeLog().getTime().printLog("Thread_B END ");
elapsed_B.setElapsedTime(start, end);
}
// Sleepのみで実処理軽い
void* thread_C(void* param)
{
TimeLog start = TimeLog().getTime().printLog("Thread_C START");
sleep(5);
TimeLog end = TimeLog().getTime().printLog("Thread_C END ");
elapsed_C.setElapsedTime(start, end);
}
//----------------------------------------------------------
// メイン処理
//----------------------------------------------------------
int main(void)
{
// メインスレッド計測開始
TimeLog main_start = TimeLog().getTime().printLog("Main START");
// スレッド起動
pthread_t tids[3];
pthread_create(&tids[0], NULL, thread_A, NULL);
pthread_create(&tids[1], NULL, thread_B, NULL);
pthread_create(&tids[2], NULL, thread_C, NULL);
// スレッド終了待ち
pthread_join(tids[0], NULL);
pthread_join(tids[1], NULL);
pthread_join(tids[2], NULL);
// メインスレッド計測終了
TimeLog main_end = TimeLog().getTime().printLog("Main END ");
elapsed_main.setElapsedTime(main_start, main_end);
// ログの表示
printf("\nElapsed Time:\n");
elapsed_main.printLog("Main");
elapsed_A.printLog("Thread_A");
elapsed_B.printLog("Thread_B");
elapsed_C.printLog("Thread_C");
return 0;
}
実行例
4コア
Main START: real=1575812537.439121016, mono=32063.696304893, boot=32063.696308226, pcpu=0.004150000, tcpu=0.004155886
Thread_A START: real=1575812537.439749506, mono=32063.696932913, boot=32063.696936038, pcpu=0.004697188, tcpu=0.000063125
Thread_B START: real=1575812537.439850391, mono=32063.697033799, boot=32063.697034945, pcpu=0.004892084, tcpu=0.000040885
Thread_C START: real=1575812537.440102943, mono=32063.697286351, boot=32063.697287705, pcpu=0.005163542, tcpu=0.000039270
Thread_C END : real=1575812542.440262790, mono=32068.697446093, boot=32068.697448385, pcpu=9.990084615, tcpu=0.000146666
Thread_A END : real=1575812545.398370708, mono=32071.655553959, boot=32071.655556043, pcpu=15.896352351, tcpu=7.957370441
Thread_B END : real=1575812553.410668627, mono=32079.667851930, boot=32079.667854222, pcpu=23.895293170, tcpu=15.932487989
Main END : real=1575812553.410906544, mono=32079.668089847, boot=32079.668092139, pcpu=23.895542597, tcpu=0.005018229
Elapsed Time:
Main: real=15.971785528, mono=15.971784954, boot=15.971783913, pcpu=23.891392597, tcpu=0.000862343
Thread_A: real=7.958621202, mono=7.958621046, boot=7.958620005, pcpu=15.891655163, tcpu=7.957307316
Thread_B: real=15.970818236, mono=15.970818131, boot=15.970819277, pcpu=23.890401086, tcpu=15.932447104
Thread_C: real=5.000159847, mono=5.000159742, boot=5.000160680, pcpu=9.984921073, tcpu=0.000107396
CLOCK_REALTIME(real)は、Unix Epoch Timeが出ています。
CLOCK_THREAD_CPUTIME_ID(tcpu) は、該当スレッドが消費したCPU時間なので、sleepしかしていない Thread_C の経過時間はほぼ0になっています。
CLOCK_PROCESS_CPUTIME_ID(pcpu) は、全スレッドの消費したCPU時間なので、Main は、Thread_AのスレッドCPU時間7.957 と Thread_BのスレッドCPU時間15.932の合計に近い値になっています。
参考元など
https://www.mm2d.net/main/prog/c/time-05.html
https://linuxjm.osdn.jp/html/LDP_man-pages/man2/clock_gettime.2.html