The `ms` in the log output is based on whose time?

[Mq-b]

[2025-02-20 14:11:59] [thread 432016] [33116ms] [info] handleFileUploadPost headers: {
    "chunk_size": 4,
    "current_chunk": 1,
    "device_id": "device_1",
    "file_name": "test.txt",
    "file_offset": 4,
    "file_type": "log",
    "password": "password_1",
    "total_chunks": 1,
    "type": "file_upload"
}
[2025-02-20 14:11:59] [thread 432016] [0ms] [info] handleFileUploadPost filePath: DeviceUploadFile/device_1/log/test.txt
[2025-02-20 14:11:59] [thread 432016] [0ms] [info] File upload completed: test.txt file_type: log filePath: DeviceUploadFile/device_1/log/test.txt
[2025-02-20 14:12:45] [thread 432017] [45804ms] [info] handleFileUploadPost headers: {
    "chunk_size": 4,
    "current_chunk": 1,
    "device_id": "device_2",
    "file_name": "test.txt",
    "file_offset": 4,
    "file_type": "result",
    "password": "password_2",
    "total_chunks": 1,
    "type": "file_upload"
}
[2025-02-20 14:12:45] [thread 432017] [0ms] [info] handleFileUploadPost filePath: DeviceUploadFile/device_2/result/test.txt
[2025-02-20 14:12:45] [thread 432017] [0ms] [info] File upload completed: test.txt file_type: result filePath: DeviceUploadFile/device_2/result/test.txt
[2025-02-20 14:13:25] [thread 432018] [39563ms] [info] handleFileUploadPost headers: {
    "chunk_size": 4,
    "current_chunk": 1,
    "device_id": "device_2",
    "file_name": "t.txt",
    "file_offset": 4,
    "file_type": "log",
    "password": "password_2",
    "total_chunks": 1,
    "type": "file_upload"
}
[2025-02-20 14:13:25] [thread 432018] [0ms] [info] handleFileUploadPost filePath: DeviceUploadFile/device_2/log/t.txt
[2025-02-20 14:13:25] [thread 432018] [0ms] [info] File upload completed: t.txt file_type: log filePath: DeviceUploadFile/device_2/log/t.txt

I use httplib to write the server and spdlog for logging.

int main() {
    setupLogging();
    
    HttpServer server;
    server.POST(HttpPatterns[Report], handleJsonPost);
    server.POST(HttpPatterns[Upload], handleFileUploadPost);

    server.listen();
}

setupLogging：

inline std::string current_time() {
    auto now = std::chrono::system_clock::now();
    auto in_time_t = std::chrono::system_clock::to_time_t(now);
    std::stringstream ss;
    ss << std::put_time(std::localtime(&in_time_t), "%Y-%m-%d");
    return ss.str();
}

inline void setupLogging() {
    if(std::filesystem::exists("Log")){
        std::filesystem::create_directory("Log");
    }
    auto file_sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(std::format("./Log/{}.log", current_time()));
    file_sink->set_level(spdlog::level::debug);
    file_sink->set_pattern("[%Y-%m-%d %H:%M:%S] [thread %t] [%oms] [%l] %v");

    auto console_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
    console_sink->set_level(spdlog::level::debug);
    console_sink->set_pattern("%^[%Y-%m-%d %H:%M:%S] [thread %t] [%oms] [%l] %v%$");

    auto logger = std::make_shared<spdlog::logger>("multi_sink", spdlog::sinks_init_list{ file_sink, console_sink });
    spdlog::register_logger(logger);

    spdlog::set_default_logger(logger);
    spdlog::flush_on(spdlog::level::debug);
}

I don't know why there are so many 0ms and I want to know what this time is based on.

[tt4g]

See Wiki: https://github.com/gabime/spdlog/wiki/3.-Custom-formatting

%o Elapsed time in milliseconds since previous message

Source code:

spdlog/include/spdlog/pattern_formatter-inl.h

Lines 767 to 785 in 3335c38

	// print elapsed time since last message
	template <typename ScopedPadder, typename Units>
	class elapsed_formatter final : public flag_formatter {
	public:
	using DurationUnits = Units;
	explicit elapsed_formatter(padding_info padinfo)
	: flag_formatter(padinfo),
	last_message_time_(log_clock::now()) {}
	void format(const details::log_msg &msg, const std::tm &, memory_buf_t &dest) override {
	auto delta = (std::max)(msg.time - last_message_time_, log_clock::duration::zero());
	auto delta_units = std::chrono::duration_cast<DurationUnits>(delta);
	last_message_time_ = msg.time;
	auto delta_count = static_cast<size_t>(delta_units.count());
	auto n_digits = static_cast<size_t>(ScopedPadder::count_digits(delta_count));
	ScopedPadder p(n_digits, padinfo_, dest);
	fmt_helper::append_int(delta_count, dest);
	}

[Mq-b]

Is it because of multithreading that I have so much 0ms?

[tt4g]

It means that the interval between the generation of the last message and the next message is less than 0 milliseconds, regardless of the thread.

[Mq-b]

ok