Due to performance issues on a project I made the following test program (even used different variables for sanity check):
#include <time.h>
#include <stdio.h>
int main()
{
struct tm *timeinfo;
time_t rawtime;
clock_t begin, end, begin1, end1,begin2,end2;
double time_spent;
begin = clock();
for (int i = 0; i < 1000000; i++){
time ( &rawtime );
timeinfo = localtime(&rawtime);
}
end = clock();
time_spent = (double)(end - begin) / CLOCKS_PER_SEC;
printf("Time elapsed using localtime() : %fs\n", time_spent);
//--------------------------------
begin1 = clock();
for (int i = 0; i < 1000000; i++){
time ( &rawtime );
timeinfo = gmtime(&rawtime);
}
end1 = clock();
time_spent = (double)(end1 - begin1) / CLOCKS_PER_SEC;
printf("Time elapsed using gmtime() : %fs\n", time_spent);
//--------------------------------
begin2 = clock();
for (int i = 0; i < 1000000; i++){
time ( &rawtime );
localtime_r( &rawtime, timeinfo);
}
end2 = clock();
time_spent = (double)(end2 - begin2) / CLOCKS_PER_SEC;
printf("Time elapsed using localtime_r() : %fs\n", time_spent);
return 0;
}
The results I get are very strange, localtime takes ~24 times more time, the localtime_r() function seems to take less than localtime(), but still a lot more than gmtime():
Time elapsed using localtime() : 0.958033s
Time elapsed using gmtime() : 0.038769s
Time elapsed using localtime_r() : 0.860276s
I've compiled it with gcc 5 as well as 4.x version, I've used linux Mint (updated to this day) and CentOS5. Also it's been tested on different physical machines and the performance difference is similar.
Why is there such a (huge) performance difference?
If you run this code under perf record and then do perf report you will notice that localtime calls getenv("TZ") on each iteration. Whereas gmtime does not.
Looking into the source code of glibc confirms the callgraphs:
gmtime
__tz_convert(, 0, )
tzset_internal(0, 1)
mktime
__tz_convert(, 1, )
tzset_internal(1, 1)
getenv("TZ")
See glibc source code of localtime,
gmtime and
__tz_convert.
perf report:
Samples: 78K of event 'cycles:u', Event count (approx.): 21051445406
Children Self Samples Command Shared Object Symbol ▒
+ 99.48% 0.59% 349 test test [.] main ▒
+ 99.48% 0.00% 0 test libc-2.23.so [.] __libc_start_main ▒
+ 99.48% 0.00% 0 test test [.] _start ▒
+ 98.02% 7.07% 4208 test libc-2.23.so [.] __tz_convert ◆
- 24.51% 23.87% 20812 test libc-2.23.so [.] getenv ▒
- 23.87% _start ▒
__libc_start_main ▒
main ▒
__tz_convert ▒
getenv ▒
+ 0.64% getenv ▒
+ 22.41% 12.75% 9877 test libc-2.23.so [.] __tzfile_compute ▒
+ 15.49% 15.49% 8025 test libc-2.23.so [.] __offtime ▒
+ 12.72% 6.28% 5476 test libc-2.23.so [.] __tzfile_read ▒
+ 9.66% 3.54% 3086 test libc-2.23.so [.] __tzstring ▒
+ 8.36% 1.40% 1221 test libc-2.23.so [.] __strdup ▒
+ 7.68% 3.38% 2946 test libc-2.23.so [.] free ▒
+ 5.98% 3.07% 2682 test libc-2.23.so [.] malloc ▒
+ 4.96% 0.68% 611 test libc-2.23.so [.] __xstat64 ▒
+ 4.30% 4.30% 3750 test libc-2.23.so [.] _int_free ▒
+ 4.28% 4.28% 3731 test [kernel.kallsyms] [k] entry_SYSCALL_64 ▒
+ 4.08% 4.08% 3564 test libc-2.23.so [.] strlen ▒
+ 3.64% 3.64% 3168 test libc-2.23.so [.] __memcmp_sse2 ▒
+ 2.91% 2.91% 2561 test libc-2.23.so [.] _int_malloc ▒
+ 1.25% 1.25% 1094 test libc-2.23.so [.] __memcpy_sse2 ▒
+ 0.68% 0.68% 587 test libc-2.23.so [.] localtime ▒
0.26% 0.26% 222 test libc-2.23.so [.] 0x000000000001f910 ▒
0.18% 0.18% 37 test test [.] gmtime@plt ▒
0.15% 0.15% 126 test test [.] localtime@plt ▒
0.11% 0.11% 23 test libc-2.23.so [.] gmtime ▒
0.01% 0.01% 6 test [kernel.kallsyms] [k] __irqentry_text_start ▒
0.00% 0.00% 3 test ld-2.23.so [.] _dl_lookup_symbol_x ▒
0.00% 0.00% 5 test ld-2.23.so [.] do_lookup_x ▒
0.00% 0.00% 2 test ld-2.23.so [.] _dl_relocate_object ▒
0.00% 0.00% 1 test libc-2.23.so [.] 0x000000000001f8e8 ▒
0.00% 0.00% 1 test ld-2.23.so [.] strlen ▒
0.00% 0.00% 1 test ld-2.23.so [.] _dl_debug_initialize ▒
0.00% 0.00% 1 test ld-2.23.so [.] _dl_start ▒
0.00% 0.00% 1 test [kernel.kallsyms] [k] page_fault ▒
0.00% 0.00% 6 test ld-2.23.so [.] _start