系统技术非业余研究

高性能网络服务器通常会涉及大量和时间相关的场景和操作，比如定时器，读取事件的发生时间，日志等等。

erlang提供了二种方式来获取时间：
1. erlang:now()
2. os:timestamp()
获取取到时间后，我们通常用calendar:now_to_universal_time来格式化类似”{{2013,11,4},{8,46,20}}”这样人可读的时间。

由于时间调用非常的频繁，而且通常发生在关键路径上，所以效率和性能就非常值得深挖了。

我们先来看下这二个函数的说明：
erlang:now 参看这里

now() -> Timestamp

Types:

Timestamp = timestamp()
timestamp() =
{MegaSecs :: integer() >= 0,
Secs :: integer() >= 0,
MicroSecs :: integer() >= 0}
Returns the tuple {MegaSecs, Secs, MicroSecs} which is the elapsed time since 00:00 GMT, January 1, 1970 (zero hour) on the assumption that the underlying OS supports this. Otherwise, some other point in time is chosen. It is also guaranteed that subsequent calls to this BIF returns continuously increasing values. Hence, the return value from now() can be used to generate unique time-stamps, and if it is called in a tight loop on a fast machine the time of the node can become skewed.

It can only be used to check the local time of day if the time-zone info of the underlying operating system is properly configured.

If you do not need the return value to be unique and monotonically increasing, use os:timestamp/0 instead to avoid some overhead.

os:timestamp 参看这里

timestamp() -> Timestamp

Types:

Timestamp = erlang:timestamp()
Timestamp = {MegaSecs, Secs, MicroSecs}
Returns a tuple in the same format as erlang:now/0. The difference is that this function returns what the operating system thinks (a.k.a. the wall clock time) without any attempts at time correction. The result of two different calls to this function is not guaranteed to be different.

The most obvious use for this function is logging. The tuple can be used together with the function calendar:now_to_universal_time/1 or calendar:now_to_local_time/1 to get calendar time. Using the calendar time together with the MicroSecs part of the return tuple from this function allows you to log timestamps in high resolution and consistent with the time in the rest of the operating system.

但是事情没这么简单!

由于erlang支持时间纠正机制，简单的说在时间发生突变的时候，还能维持正常的时间逻辑，具体的实现参看这篇：服务器时间校正思考。

时间纠正机制让事情变得复杂，这个时间纠正机制如何禁止呢：

+c
Disable compensation for sudden changes of system time.

Normally, erlang:now/0 will not immediately reflect sudden changes in the system time, in order to keep timers (including receive-after) working. Instead, the time maintained by erlang:now/0 is slowly adjusted towards the new system time. (Slowly means in one percent adjustments; if the time is off by one minute, the time will be adjusted in 100 minutes.)

When the +c option is given, this slow adjustment will not take place. Instead erlang:now/0 will always reflect the current system time. Note that timers are based on erlang:now/0. If the system time jumps, timers then time out at the wrong time.

正是由于时间纠正机制的存在，所以服务器需要不时的修正时间，同一时刻可能还有很多线程在读取时间，为了维护时间的一致性，需要有个锁来保护。
我们来看下相关的代码实现：

BIF_RETTYPE os_timestamp_0(BIF_ALIST_0)
{
    Uint megasec, sec, microsec;
    Eterm* hp;

    get_sys_now(&megasec, &sec, &microsec);
    hp = HAlloc(BIF_P, 4);
    BIF_RET(TUPLE3(hp, make_small(megasec), make_small(sec),
                   make_small(microsec)));
}
 /* return a timestamp */
BIF_RETTYPE now_0(BIF_ALIST_0)
{
    Uint megasec, sec, microsec;
    Eterm* hp;

    get_now(&megasec, &sec, &microsec);
    hp = HAlloc(BIF_P, 4);
    BIF_RET(TUPLE3(hp, make_small(megasec), make_small(sec),
                   make_small(microsec)));
}

/* get a timestamp */
void
get_now(Uint* megasec, Uint* sec, Uint* microsec)
{
    SysTimeval now;
    erts_smp_mtx_lock(&erts_timeofday_mtx);

    get_tolerant_timeofday(&now);
    do_erts_deliver_time(&now);

    /* Make sure time is later than last */
    if (then.tv_sec > now.tv_sec ||
        (then.tv_sec == now.tv_sec && then.tv_usec >= now.tv_usec)) {
        now = then;
        now.tv_usec++;
    }
    /* Check for carry from above + general reasonability */
    if (now.tv_usec >= 1000000) {
        now.tv_usec = 0;
        now.tv_sec++;
    }
    then = now;

    erts_smp_mtx_unlock(&erts_timeofday_mtx);

    *megasec = (Uint) (now.tv_sec / 1000000);
    *sec = (Uint) (now.tv_sec % 1000000);
    *microsec = (Uint) (now.tv_usec);

    update_approx_time(&now);
}

void
get_sys_now(Uint* megasec, Uint* sec, Uint* microsec)
{
    SysTimeval now;

    sys_gettimeofday(&now);

    *megasec = (Uint) (now.tv_sec / 1000000);
    *sec = (Uint) (now.tv_sec % 1000000);
    *microsec = (Uint) (now.tv_usec);

    update_approx_time(&now);
}

erlang:now在获取时间的时候需要上erts_timeofday_mtx锁，而os:timestamp则简单的调用sys_gettimeofday函数来获取，并且在linux下gettimeofday这个系统调用由于使用频度非常高，系统已经将之vdso化了，也就说去取这个时间等同于读取一个字长的内存的代价而已。

我们的proxy服务器会在各个点调用时间函数，同时我们的函数是多个调度器调度的，通过观察发现erts_timeofday_mtx是个瓶颈，我们来一起查看下erts_timeofday_mtx锁的使用情况。

我们需要使用lcnt工具来帮助我们：
首先利用Erlang包管理工具：kerl，先来编译一个带lcnt支持的版本，步骤如下：

$ KERL_CONFIGURE_OPTIONS="--enable-lock-counter" kerl build git git://github.com/erlang/otp.git master r16131104
$ kerl install r16131104 r16131104
$ r16131102/bin/erl 
Erlang R17A (erts-5.11) [source-69a0e01] [64-bit] [smp:16:16] [async-threads:10] [hipe] [kernel-poll:false] [lock-counting] 

Eshell V5.11  (abort with ^G)
1> 

当看到[lock-counting]就说明我们做对了，接着我们来模拟下多个线程同时调用erlang:now的时候锁的冲突率：

$ r16131102/bin/erl 
Erlang R17A (erts-5.11) [source-69a0e01] [64-bit] [smp:16:16] [async-threads:10] [hipe] [kernel-poll:false] [lock-counting] [systemtap]

Eshell V5.11  (abort with ^G)
1> lcnt:start().
{ok,<0.34.0>}
2> lcnt:collect(),lcnt:inspect(timeofday).  
      lock        id  #tries  #collisions  collisions [%]  time [us]  duration [%]
     -----       --- ------- ------------ --------------- ---------- -------------
 timeofday undefined    4218            0          0.0000          0        0.0000
ok
3> [spawn(fun()-> _= [ erlang:now() || _<-lists:seq(1,100000)], ok end) || _<-lists:seq(1,64)], ok.  
ok
4> lcnt:collect(),lcnt:inspect(timeofday).                                                     
      lock        id  #tries  #collisions  collisions [%]  time [us]  duration [%]
     -----       --- ------- ------------ --------------- ---------- -------------
 timeofday undefined 2049918      2042543         99.6402   23534531       10.6515
ok
5> lcnt:locations([{thresholds, [{colls,1000}]}]).
      lock                  location  #tries  #collisions  collisions [%]  time [us]  duration [%]
     -----                 --------- ------- ------------ --------------- ---------- -------------
 timeofday 'beam/erl_time_sup.c':900 2180564      2179789         99.9645   24843768      221.2510
 timeofday 'beam/erl_time_sup.c':949   17557        16407         93.4499     162706        1.4490
6> lcnt:clear().
ok
7> [spawn(fun()-> _=[os:timestamp()||_<-lists:seq(1,100000)],ok end) || _<-lists:seq(1,64)], ok.   
ok
8> lcnt:collect(),lcnt:inspect(timeofday).                                                       
      lock        id  #tries  #collisions  collisions [%]  time [us]  duration [%]
     -----       --- ------- ------------ --------------- ---------- -------------
 timeofday undefined   52666            0          0.0000          0        0.0000
ok

感谢伟大的lcnt给我们如此详细的数据。我们不仅可以看到timeofday锁的冲突率非常高，等锁化了大量的时间，还可以看到在源码哪行引起的。比如900行就是get_now函数。

从上面的分析我们可以知道取时间操作应该首选 os:timestamp().
但是现在的问题是有没有更快的方法，哪怕舍弃点精度? 答案是可以的。
看到上面函数的update_approx_time(&now)函数了吗？从名字就可以看出来在更新近似的时间。
比如Erlang进程创建的时候，会保留一个创建时间，这个时间不需要太精确，用于在类似进程crash的时候，打出时间戳。
关键代码就这行：p->approx_started = erts_get_approx_time()

不精确时间管理相关的代码如下：

static void
init_approx_time(void)
{
    erts_smp_atomic_init_nob(&approx.time, 0);
}

static ERTS_INLINE erts_approx_time_t
get_approx_time(void)
{
    return (erts_approx_time_t) erts_smp_atomic_read_nob(&approx.time);
}

static ERTS_INLINE void
update_approx_time(SysTimeval *tv)
{
    erts_approx_time_t new_secs = (erts_approx_time_t) tv->tv_sec;
    erts_approx_time_t old_secs = get_approx_time();
    if (old_secs != new_secs)
        erts_smp_atomic_set_nob(&approx.time, new_secs);
}

从代码可以看出，这个时间精确到秒，大部分时间是足够用的。问题是这个函数没有通过bif导出，我们无法直接使用。
看来只能自己想办法了，感谢erlang的NIF机制，我们可以自己写代码来解决。

我们通过nif来导出函数，最后封装成mymodule:now，输出和erlang:now是一样的，方便使用，步骤如下：

$ erl +V          
Erlang (SMP,ASYNC_THREADS,HIPE) (BEAM) emulator version 5.11

$ rebar create-app
==> p (create-app)
Writing src/myapp.app.src
Writing src/myapp_app.erl
Writing src/myapp_sup.erl

$ rebar create template=basicnif
==> p (create)
Writing src/mymodule.erl
Writing c_src/mymodule.c

$ cat > rebar.config 
{port_specs, [{"priv/mymodule.so", ["c_src/*.c"]}]}.
CTRL+D

$ diff template/src/mymodule.erl src/mymodule.erl 
4c4
<          myfunction/1]).
---
>          myfunction/0, now()]).
30c30
< myfunction(_Ref) ->
---
> myfunction() ->
42a43,46
> 
> now()->
>     X = myfunction(),
>     {X div 1000000, X rem 1000000, 0}.

$ diff template/c_src/mymodule.c c_src/mymodule.c 
1a2
> #include <time.h>
18c19
<     {"myfunction", 1, mymodule_myfunction}
---
>     {"myfunction", 0, mymodule_myfunction}
35c36,39
<     return enif_make_atom(env, "ok");
---
>   typedef unsigned long erts_approx_time_t;
>   extern erts_approx_time_t erts_get_approx_time(void);
>   erts_approx_time_t t = erts_get_approx_time();
>   return enif_make_int64(env, t);

$ rebar clean && rebar compile
==> prj (clean)
==> prj (compile)
Compiled src/myapp_sup.erl
Compiled src/mymodule.erl
Compiled src/myapp_app.erl
Compiling c_src/mymodule.c

$ erl -noshell -pa ebin -eval 'io:format("~p~n",[{mymodule:now(), os:timestamp(), erlang:now()}]).' -s erlang halt  
{{1383,553732,0},{1383,553732,641065},{1383,553732,641067}}

Bingo!看到了三种时间值，到此为止我们现在有三种方式可以获取时间（代价递减），让用户各取所需把！

小结：深入理解系统，善用工具，才能做出靠谱的东西。

祝玩的开心！