feat: add point for write using latency_tracer tool

[foreverneverer]

apache/incubator-pegasus#883

Tracing the write-path enables us to further investigate the write-performance issues and understand which stage costs most. The write-path is unusually complicated to trace because by design there're multiple concurrent tasks triggered for each write.

One op first generates 2 prepare RPCs for the 2PC procedure. Simultaneously it appends one log to the WAL on disk. After 2PC and log-write finish, the write put its content into RocksDB memtable. Unless the RocksDB is stalled, a write to RocksDB is always pretty fast given that no disk IO is involved.

The entire write path can be roughly abstracted as:

1. Receives the write-request from the client.
2. Primary broadcasts 2 prepare RPCs to its secondaries, simultaneously it writes WAL.
3. 2PC finishes, WAL finishes.
4. Put data into RocksDB.
5. Reply with success to the client.

To optimize the write path, the key stage we need to concern mostly is 2->3.

This PR(depending on #510) adds some stage point for write-operation and set the latency threshold to 1 second. The dumped point as follow:

       ***************[TRACE:mutation[33]]***************
        TRACE:name=mutation.cpp:148:add_client_request                                   , span=                 708, total=                 708, ts=1598325215128566590
        TRACE:name=replica_2pc.cpp:139:init_prepare                                      , span=                1828, total=                2536, ts=1598325215128568418
        TRACE:name=prepare_list.cpp:78:prepare                                           , span=                2684, total=                5220, ts=1598325215128571102
        TRACE:name=replica_2pc.cpp:288:send_prepare_message[127.11.0.100:34803]          , span=                2590, total=                7810, ts=1598325215128573692
        TRACE:name=replica_2pc.cpp:288:send_prepare_message[127.11.0.100:34802]          , span=               36492, total=               44302, ts=1598325215128610184
        TRACE:name=mutation_log.cpp:56:append                                            , span=               21627, total=               65929, ts=1598325215128631811
        TRACE:name=mutation_log.cpp:132:commit_pending_mutations                         , span=                5573, total=               71502, ts=1598325215128637384
        TRACE:name=mutation_log.cpp:142:operator()[commit_pending_completed]             , span=               32096, total=              103598, ts=1598325215128669480
        TRACE:name=replica_2pc.cpp:501:on_append_log_completed                           , span=               11143, total=              114741, ts=1598325215128680623
        TRACE:name=replica_2pc.cpp:328:do_possible_commit_on_primary                     , span=                1075, total=              115816, ts=1598325215128681698
        TRACE:name=replica_2pc.cpp:559:on_prepare_reply[127.11.0.100:34803]              , span=              141244, total=              257060, ts=1598325215128822942
        TRACE:name=replica_2pc.cpp:559:on_prepare_reply[127.11.0.100:34802]              , span=               10748, total=              267808, ts=1598325215128833690
        TRACE:name=replica_2pc.cpp:328:do_possible_commit_on_primary                     , span=                2397, total=              270205, ts=1598325215128836087
        TRACE:name=replica.cpp:227:execute_mutation                                      , span=                 924, total=              271129, ts=1598325215128837011
        TRACE:name=replication_app_base.cpp:476:apply_mutation                           , span=                 921, total=              272050, ts=1598325215128837932
        TRACE:name=replica.cpp:318:execute_mutation[completed]                           , span=               63593, total=              335643, ts=1598325215128901525

New Config

[replication]
+abnormal_write_trace_latency_threshold = 1000000000