I checked the clock_gettime () function used to get the current time and measure the processing time in the Linux environment, so I summarized it.
#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 */
};
You can get the time information according to the clock type specified in clk_id. Excerpts from the main clock types.
CLOCK_REALTIME Real time. Affected by system time changes.
CLOCK_MONOTONIC Elapsed time from a certain start point. It is not affected by system time changes. The starting point is not strictly specified, but it is usually the elapsed time since the power was turned on.
CLOCK_BOOTTIME Similar to CLOCK_MONOTONIC, but also includes suspended time.
CLOCK_PROCESS_CPUTIME_ID CPU time consumed by own process (total CPU time consumed by each thread)
CLOCK_THREAD_CPUTIME_ID CPU time consumed by own thread
Create the source code of what kind of time information is actually output for each. The source code and execution example are shown below.
When processing is performed in multithread, each processing start time, processing end time, and their elapsed time (difference) are confirmed.
#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;
//----------------------------------------------------------
//Time related
//----------------------------------------------------------
//timespec difference calculation function
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;
}
}
//Time log class
class TimeLog
{
private:
struct timespec real;
struct timespec mono;
struct timespec boot;
struct timespec pcpu;
struct timespec tcpu;
public:
//Get the current time
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;
}
//Elapsed time setting
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;
}
//Log output
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;
//Ordinary processing
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);
}
//Heavy processing
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);
}
//Actual processing is light only with 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);
}
//----------------------------------------------------------
//Main processing
//----------------------------------------------------------
int main(void)
{
//Main thread measurement started
TimeLog main_start = TimeLog().getTime().printLog("Main START");
//Thread 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);
//Waiting for thread to end
pthread_join(tids[0], NULL);
pthread_join(tids[1], NULL);
pthread_join(tids[2], NULL);
//End of main thread measurement
TimeLog main_end = TimeLog().getTime().printLog("Main END ");
elapsed_main.setElapsedTime(main_start, main_end);
//View log
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 cores
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
Unix Epoch Time is given for CLOCK_REALTIME (real).
CLOCK_THREAD_CPUTIME_ID (tcpu) is the CPU time consumed by the corresponding thread, so the elapsed time of Thread_C, which is only sleeping, is almost 0.
Since CLOCK_PROCESS_CPUTIME_ID (pcpu) is the CPU time consumed by all threads, Main is close to the sum of Thread_A thread CPU time 7.957 and Thread_B thread CPU time 15.932. I am.
https://www.mm2d.net/main/prog/c/time-05.html https://linuxjm.osdn.jp/html/LDP_man-pages/man2/clock_gettime.2.html
Recommended Posts