From 0e99acfd33930fc5180ac390718f4b20f2d4d7e2 Mon Sep 17 00:00:00 2001 From: Håvard Pettersen Date: Mon, 18 Nov 2019 14:29:21 +0000 Subject: use chrono instead of fastos time --- config/src/tests/frt/frt.cpp | 1 + configd/src/apps/sentinel/config-handler.cpp | 1 + fnet/src/examples/frt/rpc/rpc_proxy.cpp | 15 ++++-- fnet/src/examples/timeout/timeout.cpp | 20 +++++--- fnet/src/tests/databuffer/databuffer.cpp | 37 +++++++------- fnet/src/tests/info/info.cpp | 7 +-- fnet/src/tests/locking/castspeed.cpp | 74 ++++++++++++++-------------- fnet/src/tests/locking/drainpackets.cpp | 29 +++++------ fnet/src/tests/locking/lockspeed.cpp | 62 +++++++++++------------ fnet/src/tests/scheduling/schedule.cpp | 52 +++++++++++-------- fnet/src/tests/scheduling/sloweventloop.cpp | 11 ++--- fnet/src/tests/time/timespeed.cpp | 73 ++++++--------------------- fnet/src/vespa/fnet/iocomponent.cpp | 2 +- fnet/src/vespa/fnet/iocomponent.h | 7 ++- fnet/src/vespa/fnet/packetqueue.cpp | 14 +++--- fnet/src/vespa/fnet/scheduler.cpp | 14 +++--- fnet/src/vespa/fnet/scheduler.h | 27 ++++------ fnet/src/vespa/fnet/transport.h | 1 - fnet/src/vespa/fnet/transport_thread.cpp | 51 +++---------------- fnet/src/vespa/fnet/transport_thread.h | 8 +-- logd/src/logd/watcher.cpp | 1 + 21 files changed, 216 insertions(+), 291 deletions(-) diff --git a/config/src/tests/frt/frt.cpp b/config/src/tests/frt/frt.cpp index f489ca4c7d9..b89ffe749b0 100644 --- a/config/src/tests/frt/frt.cpp +++ b/config/src/tests/frt/frt.cpp @@ -14,6 +14,7 @@ #include #include #include +#include #include #include "config-my.h" #include "config-bar.h" diff --git a/configd/src/apps/sentinel/config-handler.cpp b/configd/src/apps/sentinel/config-handler.cpp index 7b68e6c8150..19e31755400 100644 --- a/configd/src/apps/sentinel/config-handler.cpp +++ b/configd/src/apps/sentinel/config-handler.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include diff --git a/fnet/src/examples/frt/rpc/rpc_proxy.cpp b/fnet/src/examples/frt/rpc/rpc_proxy.cpp index 1f1a3a80f2f..a61e2d37197 100644 --- a/fnet/src/examples/frt/rpc/rpc_proxy.cpp +++ b/fnet/src/examples/frt/rpc/rpc_proxy.cpp @@ -2,6 +2,7 @@ #include #include +#include #include LOG_SETUP("rpc_proxy"); @@ -83,13 +84,17 @@ ReqDone::RequestDone(FRT_RPCRequest *req) const char * RPCProxy::GetPrefix(FRT_RPCRequest *req) { - FastOS_Time t; tm currTime; tm *currTimePt; - t.SetNow(); - time_t secs = t.Secs(); - currTimePt = localtime_r(&secs, &currTime); + using clock = std::chrono::system_clock; + auto now = clock::now(); + auto since = now.time_since_epoch(); + auto secs = std::chrono::duration_cast(since); + auto ms = std::chrono::duration_cast(since - secs); + time_t my_time = clock::to_time_t(now); + + currTimePt = localtime_r(&my_time, &currTime); assert(currTimePt == &currTime); (void) currTimePt; @@ -107,7 +112,7 @@ RPCProxy::GetPrefix(FRT_RPCRequest *req) currTime.tm_hour, currTime.tm_min, currTime.tm_sec, - (int)(t.GetMicroSeconds() / 1000), + int(ms.count()), GetSession(req)->id, rid); diff --git a/fnet/src/examples/timeout/timeout.cpp b/fnet/src/examples/timeout/timeout.cpp index bba58faca55..1d6ecc11909 100644 --- a/fnet/src/examples/timeout/timeout.cpp +++ b/fnet/src/examples/timeout/timeout.cpp @@ -2,6 +2,7 @@ #include #include +#include #include LOG_SETUP("timeout"); @@ -42,8 +43,11 @@ public: int MyApp::Main() { - double ms; - FastOS_Time t; + using clock = std::chrono::steady_clock; + using ms_double = std::chrono::duration; + + ms_double ms; + clock::time_point t; FNET_PacketQueue queue; FastOS_ThreadPool pool(65000); FNET_Transport transport; @@ -57,28 +61,28 @@ MyApp::Main() FNET_Context context; fprintf(stderr, "scheduling timeout in 2 seconds...\n"); - t.SetNow(); + t = clock::now(); timeout.Schedule(2.0); // timeout in 2 seconds FastOS_Thread::Sleep(1000); timeout.Unschedule(); // cancel timeout - ms = t.MilliSecsToNow(); + ms = (clock::now() - t); if (queue.GetPacketCnt_NoLock() == 0) fprintf(stderr, "timeout canceled; no timeout packet delivered\n"); - fprintf(stderr, "time since timeout was scheduled: %f ms\n", ms); + fprintf(stderr, "time since timeout was scheduled: %f ms\n", ms.count()); fprintf(stderr, "scheduling timeout in 2 seconds...\n"); - t.SetNow(); + t = clock::now(); timeout.Schedule(2.0); // timeout in 2 seconds packet = queue.DequeuePacket(&context); // wait for timeout - ms = t.MilliSecsToNow(); + ms = (clock::now() - t); if (packet->IsTimeoutCMD()) fprintf(stderr, "got timeout packet\n"); - fprintf(stderr, "time since timeout was scheduled: %f ms\n", ms); + fprintf(stderr, "time since timeout was scheduled: %f ms\n", ms.count()); transport.ShutDown(true); pool.Close(); diff --git a/fnet/src/tests/databuffer/databuffer.cpp b/fnet/src/tests/databuffer/databuffer.cpp index 4bc3a6cb7a8..c5cfb544abd 100644 --- a/fnet/src/tests/databuffer/databuffer.cpp +++ b/fnet/src/tests/databuffer/databuffer.cpp @@ -1,7 +1,7 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. #include #include -#include +#include TEST("test resetIfEmpty") { FNET_DataBuffer buf(64); @@ -53,11 +53,14 @@ TEST("testResize") { } TEST("testSpeed") { + using clock = std::chrono::steady_clock; + using ms_double = std::chrono::duration; + FNET_DataBuffer buf0(20000); FNET_DataBuffer buf1(20000); FNET_DataBuffer buf2(20000); - FastOS_Time start; - FastOS_Time stop; + clock::time_point start; + ms_double ms; int i; int k; @@ -76,7 +79,7 @@ TEST("testSpeed") { buf0.DeadToData(buf0.GetDeadLen()); // test encode/decode speed - start.SetNow(); + start = clock::now(); for (i = 0; i < 5000; i++) { buf2.Clear(); @@ -109,15 +112,14 @@ TEST("testSpeed") { } } buf2.DeadToData(buf2.GetDeadLen()); - stop.SetNow(); - stop -= start; - fprintf(stderr, "encode/decode time (~160MB): %1.2f\n", stop.MilliSecs()); + ms = (clock::now() - start); + fprintf(stderr, "encode/decode time (~160MB): %1.2f\n", ms.count()); EXPECT_TRUE(buf0.Equals(&buf1) && buf0.Equals(&buf2)); // test encode[fast]/decode speed - start.SetNow(); + start = clock::now(); for (i = 0; i < 5000; i++) { buf2.Clear(); @@ -150,10 +152,9 @@ TEST("testSpeed") { } } buf2.DeadToData(buf2.GetDeadLen()); - stop.SetNow(); - stop -= start; - fprintf(stderr, "encode[fast]/decode time (~160MB): %1.2f\n", stop.MilliSecs()); + ms = (clock::now() - start); + fprintf(stderr, "encode[fast]/decode time (~160MB): %1.2f\n", ms.count()); EXPECT_TRUE(buf0.Equals(&buf1) && buf0.Equals(&buf2)); @@ -164,7 +165,7 @@ TEST("testSpeed") { } // test byte-swap table encoding speed - start.SetNow(); + start = clock::now(); for (i = 0; i < 10000; i++) { buf1.Clear(); @@ -179,13 +180,12 @@ TEST("testSpeed") { buf1.WriteInt32Fast(table[k + 7]); } } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "byte-swap array encoding[fast] (~160 MB): %1.2f ms\n", - stop.MilliSecs()); + ms.count()); // test direct-copy table encoding speed - start.SetNow(); + start = clock::now(); for (i = 0; i < 10000; i++) { buf2.Clear(); @@ -193,10 +193,9 @@ TEST("testSpeed") { memcpy(buf2.GetFree(), table, 16000); buf2.FreeToData(16000); } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "direct-copy array encoding (~160 MB): %1.2f ms\n", - stop.MilliSecs()); + ms.count()); } TEST_MAIN() { TEST_RUN_ALL(); } diff --git a/fnet/src/tests/info/info.cpp b/fnet/src/tests/info/info.cpp index 938ea1b7f15..a86796f5599 100644 --- a/fnet/src/tests/info/info.cpp +++ b/fnet/src/tests/info/info.cpp @@ -8,7 +8,6 @@ struct RPC : public FRT_Invokable { void GetInfo(FRT_RPCRequest *req) { - req->GetReturn()->AddString("fastos X current"); req->GetReturn()->AddString(FNET_Info::GetFNETVersion()); const char *endian_str = "UNKNOWN"; if (FNET_Info::GetEndian() == FNET_Info::ENDIAN_LITTLE) @@ -24,9 +23,8 @@ struct RPC : public FRT_Invokable { FRT_ReflectionBuilder rb(s); //------------------------------------------------------------------- - rb.DefineMethod("getInfo", "", "sssii", + rb.DefineMethod("getInfo", "", "ssii", FRT_METHOD(RPC::GetInfo), this); - // FastOS version // FNET version // endian // FD_SETSIZE @@ -56,7 +54,6 @@ TEST("info") { FRT_Values &l = *local_info->GetReturn(); // FRT_Values &r = *remote_info->GetReturn(); - fprintf(stderr, "FastOS Version: %s\n", l[0]._string._str); fprintf(stderr, "FNET Version: %s\n", l[1]._string._str); fprintf(stderr, "Endian: %s\n", l[2]._string._str); fprintf(stderr, "FD_SETSIZE: %d\n", l[3]._intval32); @@ -80,9 +77,7 @@ TEST("size of important objects") EXPECT_EQUAL(MUTEX_SIZE + 432u, sizeof(FNET_Connection)); EXPECT_EQUAL(48u, sizeof(std::condition_variable)); EXPECT_EQUAL(56u, sizeof(FNET_DataBuffer)); - EXPECT_EQUAL(24u, sizeof(FastOS_Time)); EXPECT_EQUAL(8u, sizeof(FNET_Context)); - EXPECT_EQUAL(8u, sizeof(fastos::TimeStamp)); EXPECT_EQUAL(MUTEX_SIZE, sizeof(std::mutex)); EXPECT_EQUAL(MUTEX_SIZE, sizeof(pthread_mutex_t)); EXPECT_EQUAL(48u, sizeof(pthread_cond_t)); diff --git a/fnet/src/tests/locking/castspeed.cpp b/fnet/src/tests/locking/castspeed.cpp index 153987c5516..dc82073ea57 100644 --- a/fnet/src/tests/locking/castspeed.cpp +++ b/fnet/src/tests/locking/castspeed.cpp @@ -1,6 +1,7 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. #include #include +#include class B; @@ -62,8 +63,11 @@ public: #define LOOPCNT 30000000 TEST("cast speed") { - FastOS_Time start; - FastOS_Time stop; + using clock = std::chrono::steady_clock; + using ms_double = std::chrono::duration; + + clock::time_point start; + ms_double ms; CastTest casttest; @@ -71,7 +75,7 @@ TEST("cast speed") { uint32_t i; taken = 0; - start.SetNow(); + start = clock::now(); for (i = 0; i < LOOPCNT; i++) { takeB(casttest.DummyCast()); takeB(casttest.DummyCast()); @@ -84,17 +88,16 @@ TEST("cast speed") { takeB(casttest.DummyCast()); takeB(casttest.DummyCast()); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "%d dummy cast calls: %f ms (%1.2f/us) [%f]\n", - taken, stop.MilliSecs(), - 0.001 * taken / stop.MilliSecs(), + taken, ms.count(), + 0.001 * taken / ms.count(), actualTime); taken = 0; - start.SetNow(); + start = clock::now(); for (i = 0; i < LOOPCNT; i++) { takeB(casttest.DynamicCast()); takeB(casttest.DynamicCast()); @@ -107,17 +110,16 @@ TEST("cast speed") { takeB(casttest.DynamicCast()); takeB(casttest.DynamicCast()); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "%d dynamic cast calls: %f ms (%1.2f/us) [%f]\n", - taken, stop.MilliSecs(), - 0.001 * taken / stop.MilliSecs(), + taken, ms.count(), + 0.001 * taken / ms.count(), actualTime); taken = 0; - start.SetNow(); + start = clock::now(); for (i = 0; i < LOOPCNT; i++) { takeB(casttest.TypesafeCast()); takeB(casttest.TypesafeCast()); @@ -130,17 +132,16 @@ TEST("cast speed") { takeB(casttest.TypesafeCast()); takeB(casttest.TypesafeCast()); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "%d typesafe cast calls: %f ms (%1.2f/us) [%f]\n", - taken, stop.MilliSecs(), - 0.001 * taken / stop.MilliSecs(), + taken, ms.count(), + 0.001 * taken / ms.count(), actualTime); taken = 0; - start.SetNow(); + start = clock::now(); for (i = 0; i < LOOPCNT; i++) { takeB(casttest.StaticCast()); takeB(casttest.StaticCast()); @@ -153,17 +154,16 @@ TEST("cast speed") { takeB(casttest.StaticCast()); takeB(casttest.StaticCast()); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "%d static cast calls: %f ms (%1.2f/us) [%f]\n", - taken, stop.MilliSecs(), - 0.001 * taken / stop.MilliSecs(), + taken, ms.count(), + 0.001 * taken / ms.count(), actualTime); taken = 0; - start.SetNow(); + start = clock::now(); for (i = 0; i < LOOPCNT; i++) { takeB(casttest.UnsafeCast()); takeB(casttest.UnsafeCast()); @@ -176,17 +176,16 @@ TEST("cast speed") { takeB(casttest.UnsafeCast()); takeB(casttest.UnsafeCast()); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "%d reinterpret_cast calls: %f ms (%1.2f/us) [%f]\n", - taken, stop.MilliSecs(), - 0.001 * taken / stop.MilliSecs(), + taken, ms.count(), + 0.001 * taken / ms.count(), actualTime); taken = 0; - start.SetNow(); + start = clock::now(); for (i = 0; i < LOOPCNT; i++) { takeB(casttest.DummyCast()); takeB(casttest.DummyCast()); @@ -199,13 +198,12 @@ TEST("cast speed") { takeB(casttest.DummyCast()); takeB(casttest.DummyCast()); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "%d dummy cast calls: %f ms (%1.2f/us) [%f]\n", - taken, stop.MilliSecs(), - 0.001 * taken / stop.MilliSecs(), + taken, ms.count(), + 0.001 * taken / ms.count(), actualTime); } diff --git a/fnet/src/tests/locking/drainpackets.cpp b/fnet/src/tests/locking/drainpackets.cpp index a2999f0bddc..9db43a5eb52 100644 --- a/fnet/src/tests/locking/drainpackets.cpp +++ b/fnet/src/tests/locking/drainpackets.cpp @@ -2,6 +2,7 @@ #include #include #include +#include class MyPacket : public FNET_Packet { @@ -14,8 +15,11 @@ public: TEST("drain packets") { - FastOS_Time start; - FastOS_Time stop; + using clock = std::chrono::steady_clock; + using ms_double = std::chrono::duration; + + clock::time_point start; + ms_double ms; std::mutex lock; @@ -33,7 +37,7 @@ TEST("drain packets") { // drain packets directly with single lock interval - start.SetNow(); + start = clock::now(); for (i = 0; i < 10000; i++) { @@ -59,14 +63,13 @@ TEST("drain packets") { } } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "direct, single lock interval (10M packets): %1.2f ms\n", - stop.MilliSecs()); + ms.count()); // flush packets, then move without lock - start.SetNow(); + start = clock::now(); for (i = 0; i < 10000; i++) { @@ -96,13 +99,12 @@ TEST("drain packets") { } } - stop.SetNow(); - stop -= start; - fprintf(stderr, "indirect (10M packets): %1.2f ms\n", stop.MilliSecs()); + ms = (clock::now() - start); + fprintf(stderr, "indirect (10M packets): %1.2f ms\n", ms.count()); // drain packets directly with multiple lock intervals - start.SetNow(); + start = clock::now(); for (i = 0; i < 10000; i++) { @@ -120,10 +122,9 @@ TEST("drain packets") { } } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "direct, multiple lock intervals (10M packets): %1.2f ms\n", - stop.MilliSecs()); + ms.count()); EXPECT_TRUE(q1.GetPacketCnt_NoLock() == 500 && q2.GetPacketCnt_NoLock() == 0 && diff --git a/fnet/src/tests/locking/lockspeed.cpp b/fnet/src/tests/locking/lockspeed.cpp index 50c8d4eef1b..ae6b983d724 100644 --- a/fnet/src/tests/locking/lockspeed.cpp +++ b/fnet/src/tests/locking/lockspeed.cpp @@ -2,6 +2,7 @@ #include #include #include "dummy.h" +#include class SpinLock { private: @@ -17,8 +18,12 @@ public: }; TEST("lock speed") { - FastOS_Time start; - FastOS_Time stop; + using clock = std::chrono::steady_clock; + using ms_double = std::chrono::duration; + + clock::time_point start; + ms_double ms; + DummyLock dummy; std::mutex lock; SpinLock spin; @@ -29,7 +34,7 @@ TEST("lock speed") { double spin_factor; uint32_t i; - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { dummy.Lock(); dummy.Unlock(); @@ -52,15 +57,14 @@ TEST("lock speed") { dummy.Lock(); dummy.Unlock(); } - stop.SetNow(); - stop -= start; - dummyTime = stop.MilliSecs(); + ms = (clock::now() - start); + dummyTime = ms.count(); fprintf(stderr, "10M dummy lock/unlock: %f ms (%1.2f/ms)\n", dummyTime, 10000000.0 / dummyTime); - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { lock.lock(); lock.unlock(); @@ -83,17 +87,16 @@ TEST("lock speed") { lock.lock(); lock.unlock(); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "10M actual lock/unlock: %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 10000000.0 / stop.MilliSecs()); + ms.count(), 10000000.0 / ms.count()); overhead = (actualTime - dummyTime) / 10000.0; - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { spin.lock(); spin.unlock(); @@ -116,13 +119,12 @@ TEST("lock speed") { spin.lock(); spin.unlock(); } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); + ms = (clock::now() - start); + actualTime = ms.count(); fprintf(stderr, "10M actual (spin) lock/unlock: %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 10000000.0 / stop.MilliSecs()); + ms.count(), 10000000.0 / ms.count()); spin_overhead = (actualTime - dummyTime) / 10000.0; @@ -142,7 +144,7 @@ TEST("lock speed") { //--------------------------------------------------------------------------- - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { [[maybe_unused]] std::mutex lock0; [[maybe_unused]] std::mutex lock1; @@ -155,14 +157,13 @@ TEST("lock speed") { [[maybe_unused]] std::mutex lock8; [[maybe_unused]] std::mutex lock9; } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "10M mutex create/destroy %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 10000000.0 / stop.MilliSecs()); + ms.count(), 10000000.0 / ms.count()); //--------------------------------------------------------------------------- - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { std::condition_variable cond0; std::condition_variable cond1; @@ -175,14 +176,13 @@ TEST("lock speed") { std::condition_variable cond8; std::condition_variable cond9; } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "10M cond create/destroy %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 10000000.0 / stop.MilliSecs()); + ms.count(), 10000000.0 / ms.count()); //--------------------------------------------------------------------------- - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { DummyObj dummy0; DummyObj dummy1; @@ -195,14 +195,13 @@ TEST("lock speed") { DummyObj dummy8; DummyObj dummy9; } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "10M dummy create/destroy %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 10000000.0 / stop.MilliSecs()); + ms.count(), 10000000.0 / ms.count()); //--------------------------------------------------------------------------- - start.SetNow(); + start = clock::now(); for (i = 0; i < 1000000; i++) { DummyObj *dummy0 = new DummyObj(); DummyObj *dummy1 = new DummyObj(); @@ -225,10 +224,9 @@ TEST("lock speed") { delete dummy1; delete dummy0; } - stop.SetNow(); - stop -= start; + ms = (clock::now() - start); fprintf(stderr, "10M dummy new/delete %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 10000000.0 / stop.MilliSecs()); + ms.count(), 10000000.0 / ms.count()); //--------------------------------------------------------------------------- } diff --git a/fnet/src/tests/scheduling/schedule.cpp b/fnet/src/tests/scheduling/schedule.cpp index 4ae4a2e07de..a1b02a688bf 100644 --- a/fnet/src/tests/scheduling/schedule.cpp +++ b/fnet/src/tests/scheduling/schedule.cpp @@ -2,14 +2,27 @@ #include #include -FastOS_Time _time; -FNET_Scheduler *_scheduler; +using my_clock = FNET_Scheduler::clock; +using time_point = my_clock::time_point; +using ms_double = std::chrono::duration; +time_point _time; +FNET_Scheduler *_scheduler; + +template +int as_ms(std::chrono::duration duration) { + return std::chrono::duration_cast(duration).count(); +} + +template +int as_ms(std::chrono::time_point time) { + return as_ms(time.time_since_epoch()); +} class MyTask : public FNET_Task { public: - FastOS_Time _time; + time_point _time; int _target; bool _done; @@ -24,7 +37,7 @@ public: bool Check() const { int a = _target; - int b = (int)_time.MilliSecs(); + int b = as_ms(_time); if (!_done) return false; @@ -32,7 +45,7 @@ public: if (b < a) return false; - if ((b - a) > (3 * FNET_Scheduler::SLOT_TICK)) + if ((b - a) > (3 * FNET_Scheduler::tick_ms.count())) return false; return true; @@ -66,7 +79,7 @@ public: TEST("schedule") { - _time.SetMilliSecs(0); + _time = time_point(std::chrono::milliseconds(0)); _scheduler = new FNET_Scheduler(&_time, &_time); RealTimeTask rt_task1; @@ -84,35 +97,32 @@ TEST("schedule") { assert(tasks[i] != nullptr); } - FastOS_Time start; - FastOS_Time stop; + time_point start; + ms_double ms; - start.SetNow(); + start = my_clock::now(); for (uint32_t j = 0; j < taskCnt; j++) { tasks[j]->Schedule(tasks[j]->GetTarget() / 1000.0); } - stop.SetNow(); - stop -= start; - double scheduleTime = stop.MilliSecs() / (double)taskCnt; + ms = (my_clock::now() - start); + double scheduleTime = ms.count() / (double)taskCnt; fprintf(stderr, "scheduling cost: %1.2f microseconds\n", scheduleTime * 1000.0); - start.SetNow(); + start = my_clock::now(); uint32_t tickCnt = 0; - while (_time.MilliSecs() < 135000.0) { - _time.AddMilliSecs(FNET_Scheduler::SLOT_TICK); + while (as_ms(_time) < 135000.0) { + _time += FNET_Scheduler::tick_ms; _scheduler->CheckTasks(); tickCnt++; } - stop.SetNow(); - stop -= start; - double runTime = stop.MilliSecs(); + ms = (my_clock::now() - start); fprintf(stderr, "3 RT tasks + %d one-shot tasks over 135s\n", taskCnt); - fprintf(stderr, "%1.2f seconds actual run time\n", runTime / 1000.0); + fprintf(stderr, "%1.2f seconds actual run time\n", ms.count() / 1000.0); fprintf(stderr, "%1.2f tasks per simulated second\n", (double)taskCnt / (double)135); fprintf(stderr, "%d ticks\n", tickCnt); - fprintf(stderr, "%1.2f %% simulated CPU usage\n", 100 * (runTime / 135000.0)); + fprintf(stderr, "%1.2f %% simulated CPU usage\n", 100 * (ms.count() / 135000.0)); fprintf(stderr, "%1.2f microseconds per performed task\n", - 1000.0 * (runTime / (taskCnt + tickCnt * 3.0))); + 1000.0 * (ms.count() / (taskCnt + tickCnt * 3.0))); for (uint32_t k = 0; k < taskCnt; k++) { EXPECT_TRUE(tasks[k]->Check()); diff --git a/fnet/src/tests/scheduling/sloweventloop.cpp b/fnet/src/tests/scheduling/sloweventloop.cpp index 6c218e25da5..5ddc9b1502c 100644 --- a/fnet/src/tests/scheduling/sloweventloop.cpp +++ b/fnet/src/tests/scheduling/sloweventloop.cpp @@ -17,15 +17,14 @@ public: TEST("slow event loop") { - FastOS_Time t; - t.SetMilliSecs(0); + FNET_Scheduler::time_point t(std::chrono::milliseconds(0)); FNET_Scheduler scheduler(&t, &t); MyTask task(scheduler); MyTask task2(scheduler); scheduler.CheckTasks(); - t.AddMilliSecs(10000); + t += std::chrono::milliseconds(10000); task.Schedule(5.0); uint32_t cnt = 0; @@ -35,7 +34,7 @@ TEST("slow event loop") { break; } ++cnt; - t.AddMilliSecs(1); + t += std::chrono::milliseconds(1); } if (!EXPECT_TRUE(cnt > 4700 && cnt < 4800)) { @@ -43,7 +42,7 @@ TEST("slow event loop") { } scheduler.CheckTasks(); - t.AddMilliSecs(10000); + t += std::chrono::milliseconds(10000); task2.Schedule(5.0); uint32_t cnt2 = 0; @@ -53,7 +52,7 @@ TEST("slow event loop") { break; } ++cnt2; - t.AddMilliSecs(10000); + t += std::chrono::milliseconds(10000); } if (!EXPECT_TRUE(cnt2 > 15 && cnt2 < 25)) { diff --git a/fnet/src/tests/time/timespeed.cpp b/fnet/src/tests/time/timespeed.cpp index 2b43bc6c35a..1204b0ff334 100644 --- a/fnet/src/tests/time/timespeed.cpp +++ b/fnet/src/tests/time/timespeed.cpp @@ -1,68 +1,23 @@ // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. #include #include +#include +#include +using vespalib::BenchmarkTimer; -class DummyTime -{ -public: - void SetNow() {} -}; - - -TEST("time speed") { - FastOS_Time start; - FastOS_Time stop; - DummyTime dummy; - FastOS_Time now; - double dummyTime; - double actualTime; - double overhead; - uint32_t i; - - start.SetNow(); - for (i = 0; i < 100000; i++) { - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - dummy.SetNow(); - } - stop.SetNow(); - stop -= start; - dummyTime = stop.MilliSecs(); - - fprintf(stderr, "1M dummy SetNow: %f ms (%1.2f/ms)\n", - dummyTime, 1000000.0 / dummyTime); - - start.SetNow(); - for (i = 0; i < 100000; i++) { - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - now.SetNow(); - } - stop.SetNow(); - stop -= start; - actualTime = stop.MilliSecs(); - - fprintf(stderr, "1M actual SetNow: %f ms (%1.2f/ms)\n", - stop.MilliSecs(), 1000000.0 / stop.MilliSecs()); - - overhead = (actualTime - dummyTime) / 1000.0; +TEST("steady clock speed") { + using clock = std::chrono::steady_clock; + clock::time_point t; + double min_time_us = BenchmarkTimer::benchmark([&t](){t = clock::now();}, 1.0) * 1000000.0; + fprintf(stderr, "approx overhead per sample (steady clock): %f us\n", min_time_us); +} - fprintf(stderr, "approx overhead per SetNow: %f microseconds\n", overhead); +TEST("system clock speed") { + using clock = std::chrono::system_clock; + clock::time_point t; + double min_time_us = BenchmarkTimer::benchmark([&t](){t = clock::now();}, 1.0) * 1000000.0; + fprintf(stderr, "approx overhead per sample (system clock): %f us\n", min_time_us); } TEST_MAIN() { TEST_RUN_ALL(); } diff --git a/fnet/src/vespa/fnet/iocomponent.cpp b/fnet/src/vespa/fnet/iocomponent.cpp index 0ecf63ea642..81d1bf47567 100644 --- a/fnet/src/vespa/fnet/iocomponent.cpp +++ b/fnet/src/vespa/fnet/iocomponent.cpp @@ -16,7 +16,7 @@ FNET_IOComponent::FNET_IOComponent(FNET_TransportThread *owner, _ioc_selector(nullptr), _ioc_spec(nullptr), _flags(shouldTimeOut), - _ioc_timestamp(fastos::ClockSystem::now()), + _ioc_timestamp(clock::now()), _ioc_lock(), _ioc_cond(), _ioc_refcnt(1) diff --git a/fnet/src/vespa/fnet/iocomponent.h b/fnet/src/vespa/fnet/iocomponent.h index a6a9e77ec99..84e3c8bd412 100644 --- a/fnet/src/vespa/fnet/iocomponent.h +++ b/fnet/src/vespa/fnet/iocomponent.h @@ -2,10 +2,11 @@ #pragma once -#include +#include "scheduler.h" #include #include #include +#include class FNET_TransportThread; class FNET_Config; @@ -24,6 +25,8 @@ class FNET_IOComponent FNET_IOComponent &operator=(const FNET_IOComponent &); using Selector = vespalib::Selector; + using clock = FNET_Scheduler::clock; + using time_point = clock::time_point; struct Flags { Flags(bool shouldTimeout) : @@ -47,7 +50,7 @@ protected: Selector *_ioc_selector; // attached event selector char *_ioc_spec; // connect/listen spec Flags _flags; // Compressed representation of boolean flags; - fastos::UTCTimeStamp _ioc_timestamp; // last I/O activity + time_point _ioc_timestamp; // last I/O activity std::mutex _ioc_lock; // synchronization std::condition_variable _ioc_cond; // synchronization uint32_t _ioc_refcnt; // reference counter diff --git a/fnet/src/vespa/fnet/packetqueue.cpp b/fnet/src/vespa/fnet/packetqueue.cpp index 44647d730ed..e17d5360537 100644 --- a/fnet/src/vespa/fnet/packetqueue.cpp +++ b/fnet/src/vespa/fnet/packetqueue.cpp @@ -2,7 +2,6 @@ #include "packetqueue.h" #include "packet.h" -#include #include #include @@ -226,19 +225,20 @@ FNET_PacketQueue::DequeuePacket(FNET_Context *context) FNET_Packet* FNET_PacketQueue::DequeuePacket(uint32_t maxwait, FNET_Context *context) { + using clock = std::chrono::steady_clock; FNET_Packet *packet = nullptr; - FastOS_Time startTime; - int waitTime; + clock::time_point end_time; - if (maxwait > 0) - startTime.SetNow(); + if (maxwait > 0) { + end_time = (clock::now() + std::chrono::milliseconds(maxwait)); + } std::unique_lock guard(_lock); if (maxwait > 0) { bool timeout = false; _waitCnt++; - while ((_bufused == 0) && !timeout && (waitTime = (int)(maxwait - startTime.MilliSecsToNow())) > 0) { - timeout = _cond.wait_for(guard, std::chrono::milliseconds(waitTime)) == std::cv_status::timeout; + while ((_bufused == 0) && !timeout) { + timeout = _cond.wait_until(guard, end_time) == std::cv_status::timeout; } _waitCnt--; } diff --git a/fnet/src/vespa/fnet/scheduler.cpp b/fnet/src/vespa/fnet/scheduler.cpp index 4569aaf61c4..d37b5487162 100644 --- a/fnet/src/vespa/fnet/scheduler.cpp +++ b/fnet/src/vespa/fnet/scheduler.cpp @@ -9,8 +9,8 @@ LOG_SETUP(".fnet.scheduler"); -FNET_Scheduler::FNET_Scheduler(FastOS_Time *sampler, - FastOS_Time *now) +FNET_Scheduler::FNET_Scheduler(time_point *sampler, + time_point *now) : _cond(), _next(), _now(), @@ -29,9 +29,9 @@ FNET_Scheduler::FNET_Scheduler(FastOS_Time *sampler, if (now != nullptr) { _next = *now; } else { - _next.SetNow(); + _next = clock::now(); } - _next.AddMilliSecs(SLOT_TICK); + _next += tick_ms; } @@ -69,7 +69,7 @@ FNET_Scheduler::~FNET_Scheduler() void FNET_Scheduler::Schedule(FNET_Task *task, double seconds) { - uint32_t ticks = 2 + (uint32_t) std::ceil(seconds * (1000.0 / SLOT_TICK)); + uint32_t ticks = 2 + (uint32_t) std::ceil(seconds * (1000.0 / tick_ms.count())); std::lock_guard guard(_lock); if (!task->_killed) { @@ -144,7 +144,7 @@ FNET_Scheduler::CheckTasks() if (_sampler != nullptr) { _now = *_sampler; } else { - _now.SetNow(); + _now = clock::now(); } // assume timely value propagation @@ -160,7 +160,7 @@ FNET_Scheduler::CheckTasks() // handle bucket timeout(s) - for (int i = 0; _now >= _next; ++i, _next.AddMilliSecs(SLOT_TICK)) { + for (int i = 0; _now >= _next; ++i, _next += tick_ms) { if (i < 25) { if (++_currSlot >= NUM_SLOTS) { _currSlot = 0; diff --git a/fnet/src/vespa/fnet/scheduler.h b/fnet/src/vespa/fnet/scheduler.h index 82f0de068c1..81ff8977f89 100644 --- a/fnet/src/vespa/fnet/scheduler.h +++ b/fnet/src/vespa/fnet/scheduler.h @@ -2,9 +2,9 @@ #pragma once -#include #include #include +#include class FNET_Task; @@ -19,9 +19,11 @@ class FNET_Task; class FNET_Scheduler { public: + using clock = std::chrono::steady_clock; + using time_point = clock::time_point; + static constexpr auto tick_ms = std::chrono::milliseconds(10); enum scheduler_constants { - SLOT_TICK = 10, NUM_SLOTS = 4096, SLOTS_MASK = 4095, SLOTS_SHIFT = 12 @@ -31,9 +33,9 @@ private: std::mutex _lock; std::condition_variable _cond; FNET_Task *_slots[NUM_SLOTS + 1]; - FastOS_Time _next; - FastOS_Time _now; - FastOS_Time *_sampler; + time_point _next; + time_point _now; + time_point *_sampler; uint32_t _currIter; uint32_t _currSlot; FNET_Task *_currPt; @@ -71,8 +73,8 @@ public: * @param now if given, indicates the current time. This value is * used by the constructor to init internal variables. **/ - FNET_Scheduler(FastOS_Time *sampler = nullptr, - FastOS_Time *now = nullptr); + FNET_Scheduler(time_point *sampler = nullptr, + time_point *now = nullptr); virtual ~FNET_Scheduler(); @@ -122,17 +124,6 @@ public: void Print(FILE *dst = stdout); - /** - * Obtain a pointer to the current time sampler used by this - * scheduler. The returned object may only be used in the thread - * servicing this scheduler; this includes all tasks performed by - * this scheduler. - * - * @return pointer to current time sampler. - **/ - FastOS_Time *GetTimeSampler() { return _sampler; } - - /** * Perform pending tasks. This method should be invoked regularly. **/ diff --git a/fnet/src/vespa/fnet/transport.h b/fnet/src/vespa/fnet/transport.h index 6c2aff5ec90..8d1ba48c1b0 100644 --- a/fnet/src/vespa/fnet/transport.h +++ b/fnet/src/vespa/fnet/transport.h @@ -9,7 +9,6 @@ #include #include -class FastOS_TimeInterface; class FNET_TransportThread; class FastOS_ThreadPool; class FNET_Connector; diff --git a/fnet/src/vespa/fnet/transport_thread.cpp b/fnet/src/vespa/fnet/transport_thread.cpp index b850bd6a8c2..158524d1214 100644 --- a/fnet/src/vespa/fnet/transport_thread.cpp +++ b/fnet/src/vespa/fnet/transport_thread.cpp @@ -80,7 +80,7 @@ FNET_TransportThread::RemoveComponent(FNET_IOComponent *comp) void FNET_TransportThread::UpdateTimeOut(FNET_IOComponent *comp) { - comp->_ioc_timestamp = fastos::UTCTimeStamp(_now); + comp->_ioc_timestamp = _now; RemoveComponent(comp); AddComponent(comp); } @@ -206,8 +206,7 @@ extern "C" { FNET_TransportThread::FNET_TransportThread(FNET_Transport &owner_in) : _owner(owner_in), - _startTime(), - _now(), + _now(clock::now()), _scheduler(&_now), _config(), _componentsHead(nullptr), @@ -224,10 +223,8 @@ FNET_TransportThread::FNET_TransportThread(FNET_Transport &owner_in) _started(false), _shutdown(false), _finished(false), - _waitFinished(false), - _deleted(false) + _waitFinished(false) { - _now.SetNow(); trapsigpipe(); } @@ -236,7 +233,6 @@ FNET_TransportThread::~FNET_TransportThread() { { std::lock_guard guard(_lock); - _deleted = true; } if (_started && !_finished) { LOG(error, "Transport: delete called on active object!"); @@ -386,12 +382,10 @@ bool FNET_TransportThread::InitEventLoop() { bool wasStarted; - bool wasDeleted; { std::lock_guard guard(_lock); wasStarted = _started; - wasDeleted = _deleted; - if (!_started && !_deleted) { + if (!_started) { _started = true; } } @@ -399,12 +393,7 @@ FNET_TransportThread::InitEventLoop() LOG(error, "Transport: InitEventLoop: object already active!"); return false; } - if (wasDeleted) { - LOG(error, "Transport: InitEventLoop: object was deleted!"); - return false; - } - _now.SetNow(); - _startTime = _now; + _now = clock::now(); return true; } @@ -482,45 +471,21 @@ bool FNET_TransportThread::EventLoopIteration() { FNET_IOComponent *component = nullptr; - int msTimeout = FNET_Scheduler::SLOT_TICK; - -#ifdef FNET_SANITY_CHECKS - FastOS_Time beforeGetEvents; -#endif + int msTimeout = FNET_Scheduler::tick_ms.count(); if (!IsShutDown()) { - -#ifdef FNET_SANITY_CHECKS - // Warn if event loop takes more than 250ms - beforeGetEvents.SetNow(); - double loopTime = beforeGetEvents.MilliSecs() - _now.MilliSecs(); - if (loopTime > 250.0) - LOG(warning, "SANITY: Transport loop time: %.2f ms", loopTime); -#endif - // obtain I/O events _selector.poll(msTimeout); // sample current time (performed once per event loop iteration) - _now.SetNow(); - -#ifdef FNET_SANITY_CHECKS - // Warn if event extraction takes more than timeout + 100ms - double extractTime = _now.MilliSecs() - beforeGetEvents.MilliSecs(); - if (extractTime > (double) msTimeout + 100.0) - LOG(warning, "SANITY: Event extraction time: %.2f ms (timeout: %d ms)", - extractTime, msTimeout); -#endif + _now = clock::now(); // handle wakeup and io-events _selector.dispatch(*this); // handle IOC time-outs if (_config._iocTimeOut > 0) { - - FastOS_Time t = _now; - t.SubtractMilliSecs((double)_config._iocTimeOut); - fastos::UTCTimeStamp oldest(t); + time_point oldest = (_now - std::chrono::milliseconds(_config._iocTimeOut)); while (_timeOutHead != nullptr && oldest > _timeOutHead->_ioc_timestamp) { diff --git a/fnet/src/vespa/fnet/transport_thread.h b/fnet/src/vespa/fnet/transport_thread.h index 4fc4c58107d..8bced290962 100644 --- a/fnet/src/vespa/fnet/transport_thread.h +++ b/fnet/src/vespa/fnet/transport_thread.h @@ -7,12 +7,12 @@ #include "task.h" #include "packetqueue.h" #include -#include #include #include #include #include #include +#include class FNET_Transport; class FNET_ControlPacket; @@ -30,11 +30,12 @@ class FNET_TransportThread : public FastOS_Runnable public: using Selector = vespalib::Selector; + using clock = FNET_Scheduler::clock; + using time_point = clock::time_point; private: FNET_Transport &_owner; // owning transport layer - FastOS_Time _startTime; // when event loop started - FastOS_Time _now; // current time sampler + time_point _now; // current time sampler FNET_Scheduler _scheduler; // transport thread scheduler FNET_Config _config; // FNET configuration [static] FNET_IOComponent *_componentsHead; // I/O component list head @@ -52,7 +53,6 @@ private: std::atomic _shutdown; // should stop event loop ? bool _finished; // event loop stopped ? bool _waitFinished; // someone is waiting for _finished - bool _deleted; // destructor called ? FNET_TransportThread(const FNET_TransportThread &); FNET_TransportThread &operator=(const FNET_TransportThread &); diff --git a/logd/src/logd/watcher.cpp b/logd/src/logd/watcher.cpp index 1ef9288f4da..f7e90811465 100644 --- a/logd/src/logd/watcher.cpp +++ b/logd/src/logd/watcher.cpp @@ -6,6 +6,7 @@ #include "watcher.h" #include #include +#include #include #include #include -- cgit v1.2.3