Logging to database

[GJanos]

Hello!
I am currently making a logging library, for which I use quill as a base. I am very pleased with the current features, but I have one big problem, that I cannot seem to overcome.

My main focus is to log any kinds of data (user made objects, json, basic strings) to a given database. Quill has a support for it, by enabling me to inherit from the Handler class, than overriding the write function inside it.

1. My problem is that the parameters of the write function are:

void Custom_handler::write(quill::fmt_buffer_t const &formatted_log_message, quill::TransitEvent const &log_event) {}

But here I cannot get back the metadata that got parsed to be inside of the formatted_log_message, not even the TransitEvent is containing all the metadata that is needed for me. To fix this issue I first tried to change the library ,than used string opeartions to find the related information that I needed from the formatted_log_message.

void Custom_handler::write(quill::fmt_buffer_t const &formatted_log_message, quill::TransitEvent const &log_event) {
    std::string full_log_message(formatted_log_message.data());
    std::string log_message{log_event.formatted_msg.data(), log_event.formatted_msg.size()};

    //log timestamp
    std::regex timestamp_regex(R"(\d{2}:\d{2}:\d{2}.\d{6})");
    std::smatch timestamp_match;
    std::regex_search(full_log_message, timestamp_match, timestamp_regex);
    std::string timestamp{timestamp_match[0]};

    //log level
    std::regex log_level_regex(R"(LOG_[A-Z]+)");
    std::smatch log_level_match;
    std::regex_search(full_log_message, log_level_match, log_level_regex);
    std::string log_level{log_level_match[0]};
    .
    .
}

These information can be found in the BackendWorker::_write_transit_event function as macro_metadata.

void BackendWorker::_write_transit_event(TransitEvent const& transit_event)
{
  // Forward the record to all the logger handlers
  std::pair<MacroMetadata, detail::FormatToFn> const mf = transit_event.header.metadata_and_format_fn();
  MacroMetadata const& macro_metadata = mf.first;

  for (auto& handler : transit_event.header.logger_details->handlers())
  {
    auto const& formatted_log_message_buffer = handler->formatter().format(
      std::chrono::nanoseconds{transit_event.header.timestamp}, transit_event.thread_id,
      transit_event.thread_name, _process_id, transit_event.header.logger_details->name(),
      macro_metadata, transit_event.formatted_msg);

    // If all filters are okay we write this message to the file
    if (handler->apply_filters(transit_event.thread_id,
                               std::chrono::nanoseconds{transit_event.header.timestamp},
                               macro_metadata, formatted_log_message_buffer))
    {
      // log to the handler, also pass the log_message_timestamp this is only needed in some
      // cases like daily file rotation
      handler->write(formatted_log_message_buffer, transit_event);
    }
  }
}

I tried to change the libraries code so that the MacroMetadata also gets passed into the handler->write function as a parameter, but failed. Performance is really important in my case, so I would like to remove the unnecessary string operations and somehow would make MacroMetadata available for the write function as well, because in the current case, to the best of my knowledge, there is no way to access the MacroMetadata's contents.

I am constructing log_data_info classes(that contain the metadata of the log, that are relevant for me) and pass them to functions that insert them later on into databases.

global_logger_db.insert_data(Log_data_info(std::move(timestamp),
                                                   std::move(log_level),
                                                   log_event.thread_id,
                                                   log_event.header.logger_details->name()),
                                     std::move(log_message));

Instead of this it would be so nice to just:

void Custom_handler::write(quill::fmt_buffer_t const &formatted_log_message, quill::TransitEvent const &log_event, MacroMetadata const &meta) {
    .
    .
    global_logger_db.insert_data(meta.timestamp,
                                                     meta.log_level,
                                                     log_event.thread_id,
                                                     log_event.header.logger_details->name()),
                                       std::move(log_message));
    .
    .
}

2. Quill parses whatever is passed inside of it into a string if that is possible within its macros (LOG_INFO...ect.). Is there a way to pass the objects around without converting them to a string so I can avoid these parsing related extra work?

I hope that you understood my concern, if not please write back to me so I can clarify it more. Thank you for your time!

[odygrd]

hey,

1. it is possible to retrieve the MacroMetadata in the handler. I had the same issue when i added the JsonHandler. Have a look here
   

   quill/quill/src/handlers/JsonFileHandler.cpp

   Line 9 in 525b0e0

   std::pair<MacroMetadata, detail::FormatToFn> const mf = log_event.header.metadata_and_format_fn();

e.g.

void CustomHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
{
  std::pair<MacroMetadata, detail::FormatToFn> const mf = log_event.header.metadata_and_format_fn();
  MacroMetadata const& macro_metadata = mf.first;
}

Let me know if that works for you

2. There is the hot path (the thread that is issuing the call e.g. LOG_INFO) and the non critical path that is the backend thread. When you call LOG_INFO etc the library won't convert the object to a string on the hot path as that is too expensive. Instead it will take a copy of this object. This is happening in the encode functions, for example for user defined types the object is copied here. The copy consturctor is used and is required when logging user defined types. (https://github.com/odygrd/quill/blob/master/quill/include/quill/detail/Serialize.h#L282)

Then the backend thread (which is the non critical path) will read the copy of the object and pass it to libmt for formatting (https://github.com/odygrd/quill/blob/master/quill/include/quill/detail/Serialize.h#L130)

It might worth to read this as you need to be aware of the user defined types you are logging https://github.com/odygrd/quill/blob/master/quill/include/quill/detail/Serialize.h#L130

It is also possible to pass objects as strings as you said if you use

https://quillcpp.readthedocs.io/en/latest/tutorial.html#logging-non-copy-constructible-or-unsafe-to-copy-user-defined-types

3. When logging to the database, you will have another issue. Committing single logs each time on CustomHandler::write() will be very inefficient. That will slow the backend thread and it will have less time to process the logs from the hot threads and you are running the risk of the queues that are used for the hot threads to get re-allocated. You will need to batch your commits. There are 2 ways to do it

a. Spawn another thread that is dedicated to database commits. Then pass the logs to that thread via a queue
eg.

class CustomHandler : public quill::Handler
{

CustomHandler(SPSC* queue)  : _queue(queue) {}

void CustomHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event) override
{
  std::pair<MacroMetadata, detail::FormatToFn> const mf = log_event.header.metadata_and_format_fn();
  MacroMetadata const& macro_metadata = mf.first;

  // send record to the db commit thread
  _queue.push(...)
}
};

// And a DbCommit thread that
// _queue.pop();
// batch_commits
// send the batch every eg 1 second

b. Batch your commits in CustomHandler::write and send them later. It is not possible to do that at the moment because we need to add a function that is called on the handlers periodically by the backend thread. My concern is that the backend thread will have to process the queues and also do the commits which might risk the performance of the hot threads but i don't mind adding that function. Therefore, I am recommending the first option, spawning your own thread for db commits

e.g.

class CustomHandler : public quill::Handler
{

CustomHandler() = default;

void CustomHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event) override
{
  std::pair<MacroMetadata, detail::FormatToFn> const mf = log_event.header.metadata_and_format_fn();
  MacroMetadata const& macro_metadata = mf.first;
  
  // add the log record to the commit batch
}

// Need a better name for this function
// This is called periodically by the backend worker thread and does not exist at the moment
void CustomHandler::loop() override
{
  if ((now - last_time_commited) > interval)
  {
      // commit the batch to the database
  } 
}
};

[GJanos]

Hey! Thank you for your fast and detailed response!
I have tried to access the metadata with the example you provided, and it worked!

void Custom_handler::write(quill::fmt_buffer_t const &formatted_log_message, quill::TransitEvent const &log_event) {

    std::pair<quill::MacroMetadata, quill::detail::FormatToFn> const mf = log_event.header.metadata_and_format_fn();
    quill::MacroMetadata const &macro_metadata = mf.first;
    std::string log_message{log_event.formatted_msg.data(), log_event.formatted_msg.size()};

    std::size_t type_pos = log_message.find("<<TYPE>>");
    if (type_pos == std::string::npos) {
        global_logger_db.insert_data(Log_data_info(formatter().format_timestamp(
                                                           std::chrono::nanoseconds{log_event.header.timestamp}),
                                                   quill::loglevel_to_string(macro_metadata.level()),
                                                   log_event.thread_id,
                                                   log_event.header.logger_details->name()),
                                     std::move(log_message));
        return;
    }
  .
  .

After some time, I managed to figure out how to log user defined types as well, based on the links you provided, which moved the serialization of the type off from the hot-path into the backendThread, which also helped performance.

After further research, I was able to figure out how to log any kind of, user defined or external objects as well.

Good advice on batching my commits! I haven't done anything like that, could you give me a starter there, or just say a few tips that I should pay attention to, in order to implement the batching the right way?
Hope the second batching helper function will get added soon, who knows, others might have the same difficulty as well.

Thank you for your time and asnwer!

[odygrd]

Glad to hear it worked for you !

I haven't worked much with databases, but i had a case in the past where batch commits made a huge difference in performance.
Here is an example how to do it with nanodbc if you are using an sql database (nanodbc/nanodbc#128). Almost every database supports batch operations as they make big difference in performance.

I have already added this function on the latest version which will be called when the backend thread is idle
(https://github.com/odygrd/quill/blob/master/quill/include/quill/handlers/Handler.h#L86)

You can do the batch commits there. this function will get called when the thread has no more messages to process. It has the disadvantage that if a hot thread is logging in a loop for ever, then the backend thread will always have work to do and it will never get called, but it is unlikely under real scenarios. Also keep in mind that doing too much heavy work in run_loop can affect the performance of the backend thread which is emptying the queues of the hot threads and processing the logs

[GJanos]

Hello!
You mentioned to use spsc queues for batching commits, but aren't there more backend threads, or just only one? Because if there are mpsc would be better, right?

[odygrd]

There is always a single backend thread processing all the logs, it’s not possible to spawn more

[odygrd]

@GJanos note that in the latest master I added a function that returns the Metadata from the TransitEvent. You can get them like this

void CustomHandler::write(fmt_buffer_t const& formatted_log_message, quill::TransitEvent const& log_event)
{
  MacroMetadata const macro_metadata = log_event.metadata();
}

[GJanos]

@odygrd
Thank you for informing me, I have updated my code!