Skip to content

Commit 7c36df2

Browse files
kakaiukakaiu
committed
add knob to increase priority of handshake flowlock and measure latency when error
1 parent 9edcb04 commit 7c36df2

File tree

1 file changed

+67
-27
lines changed

1 file changed

+67
-27
lines changed

‎flow/Net2.actor.cpp

Lines changed: 67 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -365,26 +365,28 @@ class BindPromise {
365365
NetworkAddress peerAddr;
366366
double createTime = 0.0;
367367
double startTime = 0.0;
368+
double startHandshakeTime = 0.0;
368369

369370
public:
370371
BindPromise(const char* errContext, UID errID) : errContext(errContext), errID(errID) {}
371372
BindPromise(AuditedEvent auditedEvent, UID errID) : errContext(auditedEvent), errID(errID) {}
372373
BindPromise(BindPromise const& r)
373374
: p(r.p), errContext(r.errContext), errID(r.errID), peerAddr(r.peerAddr), createTime(r.createTime),
374-
startTime(r.startTime) {}
375+
startTime(r.startTime), startHandshakeTime(r.startHandshakeTime) {}
375376
BindPromise(BindPromise&& r) noexcept
376377
: p(std::move(r.p)), errContext(r.errContext), errID(r.errID), peerAddr(r.peerAddr), createTime(r.createTime),
377-
startTime(r.startTime) {}
378+
startTime(r.startTime), startHandshakeTime(r.startHandshakeTime) {}
378379

379380
Future<Void> getFuture() const { return p.getFuture(); }
380381

381382
NetworkAddress getPeerAddr() const { return peerAddr; }
382383

383384
void setPeerAddr(const NetworkAddress& addr) { peerAddr = addr; }
384385

385-
void setTimeMetrics(double inputCreateTime, double inputStartTime) {
386+
void setTimeMetrics(double inputCreateTime, double inputStartTime, double inputStartHandshakeTime) {
386387
createTime = inputCreateTime;
387388
startTime = inputStartTime;
389+
startHandshakeTime = inputStartHandshakeTime;
388390
}
389391

390392
void operator()(const boost::system::error_code& error, size_t bytesWritten = 0) {
@@ -399,11 +401,7 @@ class BindPromise {
399401
else
400402
traceEvent.emplace(SevWarn, std::get<const char*>(errContext), errID);
401403
TraceEvent& evt = *traceEvent;
402-
evt.suppressFor(1.0)
403-
.detail("ErrorCode", error.value())
404-
.detail("Message", error.message())
405-
.detail("Duration", currentTime - createTime)
406-
.detail("ProcessTime", currentTime - startTime);
404+
evt.suppressFor(1.0).detail("ErrorCode", error.value()).detail("Message", error.message());
407405
// There is no function in OpenSSL to use to check if an error code is from OpenSSL,
408406
// but all OpenSSL errors have a non-zero "library" code set in bits 24-32, and linux
409407
// error codes should never go that high.
@@ -415,6 +413,15 @@ class BindPromise {
415413
evt.detail("PeerAddr", peerAddr);
416414
evt.detail("PeerAddress", peerAddr);
417415
}
416+
if (createTime > 0) {
417+
evt.detail("Duration", currentTime - createTime);
418+
}
419+
if (startTime > 0) {
420+
evt.detail("QueuingTime", currentTime - startTime);
421+
}
422+
if (startHandshakeTime > 0) {
423+
evt.detail("ServiceTime", currentTime - startHandshakeTime);
424+
}
418425
}
419426

420427
p.sendError(connection_failed());
@@ -847,9 +854,10 @@ struct SSLHandshakerThread final : IThreadPoolReceiver {
847854
return std::move(o).str();
848855
}
849856

850-
void setTimeMetrics(double inputCreateTime, double inputStartTime) {
857+
void setTimeMetrics(double inputCreateTime, double inputStartTime, double inputStartHandshakeTime) {
851858
createTime = inputCreateTime;
852859
startTime = inputStartTime;
860+
startHandshakeTime = inputStartHandshakeTime;
853861
}
854862

855863
ThreadReturnPromise<Void> done;
@@ -858,10 +866,12 @@ struct SSLHandshakerThread final : IThreadPoolReceiver {
858866
boost::system::error_code err;
859867
double createTime = 0.0;
860868
double startTime = 0.0;
869+
double startHandshakeTime = 0.0;
861870
};
862871

863872
void action(Handshake& h) {
864873
try {
874+
double currentTime = now();
865875
h.socket.next_layer().non_blocking(false, h.err);
866876
if (!h.err.failed()) {
867877
h.socket.handshake(h.type, h.err);
@@ -870,17 +880,23 @@ struct SSLHandshakerThread final : IThreadPoolReceiver {
870880
h.socket.next_layer().non_blocking(true, h.err);
871881
}
872882
if (h.err.failed()) {
873-
double currentTime = now();
874-
TraceEvent(SevWarn,
875-
h.type == ssl_socket::handshake_type::client ? "N2_ConnectHandshakeError"_audit
876-
: "N2_AcceptHandshakeError"_audit)
877-
.detail("PeerAddr", h.getPeerAddress())
878-
.detail("PeerAddress", h.getPeerAddress())
879-
.detail("ErrorCode", h.err.value())
880-
.detail("ErrorMsg", h.err.message().c_str())
881-
.detail("BackgroundThread", true)
882-
.detail("Duration", currentTime - h.createTime)
883-
.detail("ProcessTime", currentTime - h.startTime);
883+
TraceEvent evt(SevWarn,
884+
h.type == ssl_socket::handshake_type::client ? "N2_ConnectHandshakeError"_audit
885+
: "N2_AcceptHandshakeError"_audit);
886+
evt.detail("PeerAddr", h.getPeerAddress());
887+
evt.detail("PeerAddress", h.getPeerAddress());
888+
evt.detail("ErrorCode", h.err.value());
889+
evt.detail("ErrorMsg", h.err.message().c_str());
890+
evt.detail("BackgroundThread", true);
891+
if (h.createTime > 0) {
892+
evt.detail("Duration", currentTime - h.createTime);
893+
}
894+
if (h.startTime > 0) {
895+
evt.detail("QueuingTime", currentTime - h.startTime);
896+
}
897+
if (h.startHandshakeTime > 0) {
898+
evt.detail("ServiceTime", currentTime - h.startHandshakeTime);
899+
}
884900
h.done.sendError(connection_failed());
885901
} else {
886902
h.done.send(Void());
@@ -966,6 +982,8 @@ class SSLConnection final : public IConnection, ReferenceCounted<SSLConnection>
966982

967983
ACTOR static void doAcceptHandshake(Reference<SSLConnection> self, Promise<Void> connected) {
968984
state Hold<int> holder;
985+
state double startHandshakeTime = now();
986+
state bool doBackgroundHandshake = false;
969987

970988
try {
971989
Future<Void> onHandshook;
@@ -981,20 +999,31 @@ class SSLConnection final : public IConnection, ReferenceCounted<SSLConnection>
981999
holder = Hold(&N2::g_net2->sslPoolHandshakesInProgress);
9821000
auto handshake =
9831001
new SSLHandshakerThread::Handshake(self->ssl_sock, boost::asio::ssl::stream_base::server);
984-
handshake->setTimeMetrics(self->createTime, self->startTime);
1002+
handshake->setTimeMetrics(self->createTime, self->startTime, startHandshakeTime);
9851003
onHandshook = handshake->done.getFuture();
1004+
doBackgroundHandshake = true;
9861005
N2::g_net2->sslHandshakerPool->post(handshake);
9871006
} else {
9881007
// Otherwise use flow network thread
9891008
g_net2->countServerTLSHandshakesOnMainThread++;
9901009
BindPromise p("N2_AcceptHandshakeError"_audit, self->id);
9911010
p.setPeerAddr(self->getPeerAddress());
992-
p.setTimeMetrics(self->createTime, self->startTime);
1011+
p.setTimeMetrics(self->createTime, self->startTime, startHandshakeTime);
9931012
onHandshook = p.getFuture();
1013+
doBackgroundHandshake = false;
9941014
self->ssl_sock.async_handshake(boost::asio::ssl::stream_base::server, std::move(p));
9951015
}
9961016
wait(onHandshook);
9971017
wait(delay(0, TaskPriority::Handshake));
1018+
double currentTime = now();
1019+
TraceEvent(SevInfo, "N2_AcceptHandshakeComplete"_audit)
1020+
.suppressFor(1.0)
1021+
.detail("PeerAddr", self->getPeerAddress())
1022+
.detail("PeerAddress", self->getPeerAddress())
1023+
.detail("BackgroundThread", doBackgroundHandshake)
1024+
.detail("Duration", currentTime - self->createTime)
1025+
.detail("QueuingTime", currentTime - self->startTime)
1026+
.detail("ServiceTime", currentTime - startHandshakeTime);
9981027
connected.send(Void());
9991028
} catch (...) {
10001029
self->closeSocket();
@@ -1021,9 +1050,7 @@ class SSLConnection final : public IConnection, ReferenceCounted<SSLConnection>
10211050
}
10221051
}
10231052

1024-
wait(g_network->networkInfo.handshakeLock->take(FLOW_KNOBS->TLS_HANDSHAKE_FLOWLOCK_HIGH_PRIORITY
1025-
? TaskPriority::AcceptSocket
1026-
: TaskPriority::DefaultYield));
1053+
wait(g_network->networkInfo.handshakeLock->take());
10271054
state FlowLock::Releaser releaser(*g_network->networkInfo.handshakeLock);
10281055

10291056
Promise<Void> connected;
@@ -1058,6 +1085,8 @@ class SSLConnection final : public IConnection, ReferenceCounted<SSLConnection>
10581085

10591086
ACTOR static void doConnectHandshake(Reference<SSLConnection> self, Promise<Void> connected) {
10601087
state Hold<int> holder;
1088+
state double startHandshakeTime = now();
1089+
state bool doBackgroundHandshake = false;
10611090

10621091
try {
10631092
Future<Void> onHandshook;
@@ -1080,20 +1109,31 @@ class SSLConnection final : public IConnection, ReferenceCounted<SSLConnection>
10801109
holder = Hold(&N2::g_net2->sslPoolHandshakesInProgress);
10811110
auto handshake =
10821111
new SSLHandshakerThread::Handshake(self->ssl_sock, boost::asio::ssl::stream_base::client);
1083-
handshake->setTimeMetrics(self->createTime, self->startTime);
1112+
handshake->setTimeMetrics(self->createTime, self->startTime, startHandshakeTime);
10841113
onHandshook = handshake->done.getFuture();
1114+
doBackgroundHandshake = true;
10851115
N2::g_net2->sslHandshakerPool->post(handshake);
10861116
} else {
10871117
// Otherwise use flow network thread
10881118
g_net2->countClientTLSHandshakesOnMainThread++;
10891119
BindPromise p("N2_ConnectHandshakeError"_audit, self->id);
10901120
p.setPeerAddr(self->getPeerAddress());
1091-
p.setTimeMetrics(self->createTime, self->startTime);
1121+
p.setTimeMetrics(self->createTime, self->startTime, startHandshakeTime);
10921122
onHandshook = p.getFuture();
1123+
doBackgroundHandshake = false;
10931124
self->ssl_sock.async_handshake(boost::asio::ssl::stream_base::client, std::move(p));
10941125
}
10951126
wait(onHandshook);
10961127
wait(delay(0, TaskPriority::Handshake));
1128+
double currentTime = now();
1129+
TraceEvent(SevInfo, "N2_ConnectHandshakeComplete"_audit)
1130+
.suppressFor(1.0)
1131+
.detail("PeerAddr", self->getPeerAddress())
1132+
.detail("PeerAddress", self->getPeerAddress())
1133+
.detail("BackgroundThread", doBackgroundHandshake)
1134+
.detail("Duration", currentTime - self->createTime)
1135+
.detail("QueuingTime", currentTime - self->startTime)
1136+
.detail("ServiceTime", currentTime - startHandshakeTime);
10971137
connected.send(Void());
10981138
} catch (...) {
10991139
self->closeSocket();

0 commit comments

Comments
 (0)