perl mktime,strftime,timelocal性能問題

sjdy521

使用過程中發(fā)現(xiàn)，調(diào)用時間處理函數(shù)產(chǎn)生性能瓶頸
利用strace發(fā)現(xiàn)瓶頸主要是因為程序大量調(diào)用stat導致，比如：

strace perl -MTime::Local -e 'print timelocal(0,0,0,27,7,2014-1900)'
....
open("/etc/localtime", O_RDONLY)        = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
fstat(4, {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ab1c8a57000
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 389
lseek(4, -226, SEEK_CUR)                = 163
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 226
close(4)                                = 0
munmap(0x2ab1c8a57000, 4096)            = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
close(3)                                = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
write(1, "1409068800", 101409068800)              = 10
exit_group(0)

可以看到一次timelocal，居然調(diào)用了5次的stat("/etc/localtime"


換用POSIX::mktime發(fā)現(xiàn)情況有好轉(zhuǎn)，調(diào)用stat("/etc/localtime"的次數(shù)變?yōu)?次
strace perl -MPOSIX=mktime -e 'print mktime(0,0,0,27,7,2014-1900)'
....
open("/etc/localtime", O_RDONLY)        = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b40c48da000
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 389
lseek(3, -226, SEEK_CUR)                = 163
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 226
close(3)                                = 0
munmap(0x2b40c48da000, 4096)            = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=389, ...}) = 0
write(1, "1409068800", 101409068800)              = 10
exit_group(0)

benchmark測試結(jié)果，在一般情況下mktime的性能也確實因為stat調(diào)用少而遠高于timelocal

use Benchmark qw(:all) ;
use POSIX qw(mktime);
use Time::Local qw(timelocal);

sub test1{
    mktime(0,0,0,26,7,114,0,0,-1);
}

sub test2{
    timelocal(0,0,0,26,7,114);
}

timethese(1000000, {
        Name1=>"test1",
        Name2=>"test2",
    }
);


Benchmark: timing 1000000 iterations of Name1, Name2...
     Name1:  5 wallclock secs ( 1.99 usr +  2.85 sys =  4.84 CPU) @ 206611.57/s (n=1000000)
     Name2: 27 wallclock secs (19.68 usr +  7.04 sys = 26.72 CPU) @ 37425.15/s (n=1000000)

為什么為頻繁的去讀取/etc/localtime文件呢，感到很奇怪，查了下這個文件的作用以及tzset()、timezone()等系統(tǒng)函數(shù)，才有所感悟，man tzset里有這樣一段：

The tzset() function initializes the tzname variable from the TZ environment variable.
       This function is automatically called by the  other  time  conversion  functions  that
       depend  on  the  time zone.  In a SysV-like environment it will also set the variables
       timezone (seconds West of GMT) and daylight (0 if this time zone  does  not  have  any
       daylight savings time rules, non-zero if there is a time during the year when daylight
       savings time applies).

       If the TZ variable does not appear in the environment, the tzname variable is initial-
       ized  with  the  best  approximation  of  local  wall  clock time, as specified by the
       tzfile(5)-format file localtime found in the system timezone  directory  (see  below).
       (One also often sees /etc/localtime used here, a symlink to the right file in the sys-
       tem timezone directory.)

       If the TZ variable does appear in the environment but its value is empty or its  value
       cannot  be interpreted using any of the formats specified below, Coordinated Universal
       Time (UTC) is used.

可以看到因為沒有設置時區(qū)信息，系統(tǒng)會去讀取/etc/localtime來獲取相關(guān)的時區(qū)信息，這才導致stat調(diào)用的比較多
程序本身就是使用UTC，設置下$ENV{TZ}= "";
再strace下發(fā)現(xiàn)mktime已經(jīng)不再去open或者stat /etc/localtime文件了 重新測試發(fā)現(xiàn)Benchmark性能也提升了4倍

Benchmark: timing 1000000 iterations of Name1, Name2...
     Name1:  1 wallclock secs ( 1.24 usr +  0.00 sys =  1.24 CPU) @ 806451.61/s (n=1000000)
     Name2:  9 wallclock secs ( 8.11 usr +  0.00 sys =  8.11 CPU) @ 123304.56/s (n=1000000)

另外，想吐槽的一點是，Time::Local模塊是perl發(fā)行版內(nèi)置的模塊，官方的描述是“efficiently compute time from local and GMT time”
但和mktime相比性能差別很大，這算哪門子efficiently。�？磥硪院筮�是不敢用Time::Local::timelocal()了

q1208c

請教樓主, 為啥忽然對 time 函數(shù)的性能這么關(guān)心了?

難道你和程序里要不停的取當前時間么?

sjdy521

回復 2# q1208c


    時間戳和字符串的轉(zhuǎn)換這種場景很多啊，比如你的webserver或者其他的server，通常都要不停的打印日志，日志里一般都會包含字符串形式的時間，肯定也是時間戳轉(zhuǎn)換來的
   
    我的程序是做訪問日志分析，需要把訪問日日志里形如[22/Aug/2014:00:00:00 +0800]的字符串形式的時間轉(zhuǎn)換問時間戳然后進行相關(guān)的時間計算，會大量的調(diào)用mktime

q1208c

回復 3# sjdy521

對于分析日志, 我覺得這點時間還是可以接受的.

如果是生成日志, 這個時間是不能接受的.

不過, 我現(xiàn)在改用 HiRes 來處理時間了, 沒注意過效率. 因為我需要的精度比 秒 要更高. 至少需要 ms 或者 us 級別.
   

sjdy521

回復 2# q1208c


    不是time() 是mktime()

sjdy521

回復 4# q1208c


    你沒明白我整個事情，這個問題和精度無關(guān)

q1208c

回復 6# sjdy521

你也沒明白我在說什么, 我說的也和精度無關(guān).
   

laputa73

直接記錄unix原始秒 就不會有性能問題.
timelocal有問題, (字符串轉(zhuǎn)秒)
那localtime是否也有問題?(秒轉(zhuǎn)字符串)

另,凡是要用到localtime的地方,必須先設時區(qū),這個是對系統(tǒng)安裝的要求
否則差8小時的情況很常見