Add logging for some slow operations.

This commit is contained in:
levlam 2022-09-15 15:03:19 +03:00
parent e087521b01
commit 111018eadd
2 changed files with 20 additions and 2 deletions

View File

@ -25,6 +25,7 @@
#include "td/utils/SliceBuilder.h"
#include "td/utils/Status.h"
#include "td/utils/StorerBase.h"
#include "td/utils/Timer.h"
#include <memory>
#include <utility>
@ -247,10 +248,11 @@ class RawConnectionDefault final : public RawConnection {
if (has_error_) {
return Status::Error("Connection has already failed");
}
PerfWarningTimer timer("RawConnection::do_flush", 0.01);
sync_with_poll(socket_fd_);
// read/write
// EINVAL may be returned in linux kernel < 2.6.28. And on some new kernels too.
// EINVAL can be returned in Linux kernel < 2.6.28. And on some new kernels too.
// just close connection and hope that read or write will not return this error too.
TRY_STATUS(socket_fd_.get_pending_error());

View File

@ -151,6 +151,7 @@ using SslCtx = std::shared_ptr<SSL_CTX>;
struct SslHandleDeleter {
void operator()(SSL *ssl_handle) {
auto start_time = Time::now();
if (SSL_is_init_finished(ssl_handle)) {
clear_openssl_errors("Before SSL_shutdown");
SSL_set_quiet_shutdown(ssl_handle, 1);
@ -158,6 +159,10 @@ struct SslHandleDeleter {
clear_openssl_errors("After SSL_shutdown");
}
SSL_free(ssl_handle);
auto elapsed_time = Time::now() - start_time;
if (elapsed_time >= 0.001) {
LOG(ERROR) << "SSL_free took " << elapsed_time << " seconds";
}
}
};
@ -289,7 +294,13 @@ Result<SslCtx> create_ssl_ctx(CSlice cert_file, SslStream::VerifyPeer verify_pee
return get_default_unverified_ssl_ctx();
}
}
return do_create_ssl_ctx(cert_file, verify_peer);
auto start_time = Time::now();
auto result = do_create_ssl_ctx(cert_file, verify_peer);
auto elapsed_time = Time::now() - start_time;
if (elapsed_time >= 0.01) {
LOG(ERROR) << "do_create_ssl_ctx took " << elapsed_time << " seconds";
}
return result;
}
} // namespace
@ -381,7 +392,12 @@ class SslStreamImpl {
Result<size_t> read(MutableSlice slice) {
clear_openssl_errors("Before SslFd::read");
auto start_time = Time::now();
auto size = SSL_read(ssl_handle_.get(), slice.data(), static_cast<int>(slice.size()));
auto elapsed_time = Time::now() - start_time;
if (elapsed_time >= 0.01) {
LOG(ERROR) << "SSL_read took " << elapsed_time << " seconds and returned " << size;
}
if (size <= 0) {
return process_ssl_error(size);
}