Add duration time to various Altimeter logs

include/tateyama/altimeter/events.h

@@ -40,6 +40,7 @@ static constexpr std::string_view remote_host = "remote_host";
 static constexpr std::string_view application_name = "application_name";
 static constexpr std::string_view session_id = "session_id";
 static constexpr std::string_view session_label = "session_label";
+static constexpr std::string_view duration_time = "duration_time";
 }
 
 // event log level list
@@ -64,6 +65,7 @@ static constexpr std::string_view remote_host = "remote_host";
 static constexpr std::string_view application_name = "application_name";
 static constexpr std::string_view result = "result";
 static constexpr std::string_view command = "command";
+static constexpr std::string_view duration_time = "duration_time";
 }
 
 // audit log level list

include/tateyama/framework/server.h

@@ -18,6 +18,7 @@
 #include <functional>
 #include <memory>
 #include <type_traits>
+#include <chrono>
 
 #include <tateyama/framework/environment.h>
 #include <tateyama/framework/component.h>
@@ -136,6 +137,9 @@ class server {
 private:
     std::shared_ptr<environment> environment_{std::make_shared<environment>()};
     bool setup_done_{false};
+#ifdef ENABLE_ALTIMETER
+    std::chrono::time_point<std::chrono::high_resolution_clock> db_start_time_{};
+#endif
 };
 
 /**

src/tateyama/endpoint/altimeter/logger.h

@@ -58,7 +58,7 @@ static inline void session_start(const tateyama::api::server::database_info& dat
     }
 }
 
-static inline void session_end(const tateyama::api::server::database_info& database_info, const tateyama::api::server::session_info& session_info) {
+static inline void session_end(const tateyama::api::server::database_info& database_info, const tateyama::api::server::session_info& session_info, std::int64_t duration_time) {
     if (::altimeter::logger::is_log_on(log_category::event,
                                      log_level::event::info)) {
         ::altimeter::log_item log_item;
@@ -79,6 +79,7 @@ static inline void session_end(const tateyama::api::server::database_info& datab
             log_item.add(log_item::event::session_label, session_label);
         }
         log_item.add(log_item::event::session_id, static_cast<std::int64_t>(session_info.id()));
+        log_item.add(log_item::event::duration_time, duration_time);
         ::altimeter::logger::log(log_item);
     }
 }

src/tateyama/endpoint/ipc/bootstrap/ipc_worker.cpp

@@ -13,6 +13,7 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+#include <chrono>
 #include <exception>
 
 #include "ipc_worker.h"
@@ -48,6 +49,7 @@ void ipc_worker::run() {
 
     VLOG(log_debug_timing_event) << "/:tateyama:timing:session:started " << session_id_;
 #ifdef ENABLE_ALTIMETER
+    const std::chrono::time_point session_start_time = std::chrono::high_resolution_clock::now();
     tateyama::endpoint::altimeter::session_start(database_info_, session_info_);
 #endif
     while(true) {
@@ -141,7 +143,7 @@ void ipc_worker::run() {
     wire_->get_response_wire().notify_shutdown();
     VLOG_LP(log_trace) << "destroy session wire: session_id = " << std::to_string(session_id_);
 #ifdef ENABLE_ALTIMETER
-    tateyama::endpoint::altimeter::session_end(database_info_, session_info_);
+    tateyama::endpoint::altimeter::session_end(database_info_, session_info_, std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - session_start_time).count());
 #endif
     VLOG(log_debug_timing_event) << "/:tateyama:timing:session:finished " << session_id_;
 }

src/tateyama/endpoint/stream/bootstrap/stream_worker.cpp

@@ -13,6 +13,8 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+#include <chrono>
+
 #include "stream_worker.h"
 
 #ifdef ENABLE_ALTIMETER
@@ -71,6 +73,7 @@ void stream_worker::run()
 
     VLOG(log_debug_timing_event) << "/:tateyama:timing:session:started " << std::to_string(session_id_);
 #ifdef ENABLE_ALTIMETER
+    const std::chrono::time_point session_start_time = std::chrono::high_resolution_clock::now();
     tateyama::endpoint::altimeter::session_start(database_info_, session_info_);
 #endif
     while(true) {
@@ -156,7 +159,7 @@ void stream_worker::run()
     session_stream_->close();
 
 #ifdef ENABLE_ALTIMETER
-    tateyama::endpoint::altimeter::session_end(database_info_, session_info_);
+    tateyama::endpoint::altimeter::session_end(database_info_, session_info_, std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - session_start_time).count());
 #endif
     VLOG(log_debug_timing_event) << "/:tateyama:timing:session:finished " << session_id_;
 }

src/tateyama/framework/altimeter_logger.h

@@ -50,7 +50,7 @@ static inline void db_start(std::string_view user, std::string_view dbname, std:
     }
 }
 
-static inline void db_stop(std::string_view user, std::string_view dbname, std::int64_t result) {
+static inline void db_stop(std::string_view user, std::string_view dbname, std::int64_t result, std::int64_t duration_time) {
     if (::altimeter::logger::is_log_on(log_category::audit,
                                      log_level::audit::info)) {
         ::altimeter::log_item log_item;
@@ -64,6 +64,7 @@ static inline void db_stop(std::string_view user, std::string_view dbname, std::
             log_item.add(log_item::audit::dbname, dbname);
         }
         log_item.add(log_item::audit::result, result);
+        log_item.add(log_item::audit::duration_time, duration_time);
         ::altimeter::logger::log(log_item);
     }
 }

src/tateyama/framework/server.cpp

@@ -100,6 +100,7 @@ bool server::setup() {
         LOG(ERROR) << "Server application framework setup phase failed.";
         // shutdown already setup components
 #ifdef ENABLE_ALTIMETER
+        db_start_time_ = std::chrono::high_resolution_clock::now();
         db_start("", get_database_name(*environment_), db_start_stop_fail);
 #endif
         shutdown();
@@ -134,17 +135,15 @@ bool server::start() {
         success = arg.start(*environment_);
         VLOG(log_info) << "/:tateyama:lifecycle:component:start_end " << arg.label() << " success:" << utils::boolalpha(success);
     });
+#ifdef ENABLE_ALTIMETER
+    db_start_time_ = std::chrono::high_resolution_clock::now();
+    db_start("", get_database_name(*environment_), success ? db_start_stop_success : db_start_stop_fail);
+#endif
     if(! success) {
         LOG(ERROR) << "Server application framework start phase failed.";
         // shutdown already started components
-#ifdef ENABLE_ALTIMETER
-        db_start("", get_database_name(*environment_), db_start_stop_fail);
-#endif
         shutdown();
     }
-#ifdef ENABLE_ALTIMETER
-    db_start("", get_database_name(*environment_), db_start_stop_success);
-#endif
     return success;
 }
 
@@ -167,7 +166,7 @@ bool server::shutdown() {
         VLOG(log_info) << "/:tateyama:lifecycle:component:shutdown_end " << arg.label();
     }, true);
 #ifdef ENABLE_ALTIMETER
-        db_stop("", get_database_name(*environment_), db_start_stop_success);
+    db_stop("", get_database_name(*environment_), db_start_stop_success, std::chrono::duration_cast<std::chrono::nanoseconds>(std::chrono::high_resolution_clock::now() - db_start_time_).count());
 #endif
     return success;
 }