C++ Async Logging
Logging을 해보자!
일반적인 소프트웨어 경우 Logging은 필수다. 그렇기 어떻게 Logging을 할 수 있고 어떤식으로 Logging을 구현하는 것이 효율적인것인가에 대해 알아볼것이다.
Logging의 중요성 : 인터넷에 검색해보면 자세히 나온다.
일반적인 IO의 문제점
Logging을 하기위해 가장 많이 쓰이면서 간단한 방법은 Synchronous하게 IO를 작동시키는것이다. 즉, 코드실행중간에 Logging 코드를 실행하여 File에 Write또는 Read하는 것이다. 아래 코드를 살펴보자
#include <iostream>
#include <fstream>
class Logging{
private:
std::ofstream file;
void writeFile(std::string msg){
file << msg << "\n";
}
public:
Logging(std::string path) : file(path){
}
void info(std::string msg){
writeFile("[INFO]" + msg);
}
~Logging(){
file << std::flush;
}
};
int main(void){
Logging logging("log.txt");
logging.info("Start Server...!");
}매우 간단한 로깅 클래스다. 이 코드에는 여러 문제점이 존재한다. 먼저 IO를 싱글 스레드에서 해버리기때문에 병목현상이 발생하게 된다.
일반적으로 IO작업은 In-Memory 작업이 아니기 때문에 file<<msg 부분에서 스레드는 IO작업이 완료되기까지 기다려야하는 상황이 발생하여 CPU 낭비이다.
또한, 기본적으로 ostream을 상속받는 것들은 기본적으로 streambuf를 상속받기 때문에 자체적인 buffer를 가지고 있다. 기본적인 buffer 사이즈를 활용하기 때문에 write API가 많이 또는 적게 호출 될 수 있다.
Streambuf ???
streambuf라는 새로운 용어가 튀어나왔다. 새롭게 들리겠지만 C++에서 IO 코드를 사용하면서 나도 모르게 쓰여지는 클래스이다. streambuf class는 입력버퍼 및 출력버퍼를 의미한다고 생각하면 된다. 쉽게말해서 출력버퍼가 없다면 아래의 코드는 곧바로 IO를 동작시키게 되고 성능저하가 발생하게 된다.
std::cout<<"Hello World";
std::cout<<"Good World"; 하지만 streambuf를 사용하게 되면 출력요청할때마다 IO를 하는것이 아닌 해당 문자열을 buffer에 넣어뒀다가 buffer가 overflow되거나 소멸자가 작동할때, flush가 발생하게 될때 IO를 사용하게 되어 성능면에서 이득을 볼 수 있다.
즉, 우리는 streambuf를 사용해서 custom buffer를 만들고 overflow와 sync 가상 메소드를 오버라이드하면 된다.
- overflow method : buffer가 꽉차게 되면 호출되는 method
- argument : int_type ch → buffer가 넘치게 되어 담지 못하는 문자 하나
- sync method : file에 write 하기 위한 메소드 flush를 사용하면 호출된다.
- pbump(int count) 및 pptr()
- → pbump()메소드는 지정된 buffer에 count만큼 늘려준다.
- → pptr()메소드는 buffer내에 현재 가리키고 있는 포인터의 다음 포인터를 반환한다.
- → 위의 2개의 메소드를 통해서 overflow됐을 때 buffer에 담지 못한 문자 하나를 담을 수 있다.
- setp(char_type* start, char_type* end)
- → buffer를 지정한다.
- ostream async_buffer(streambuf* buffer);
- → ostream에 활용할 custom buffer를 생성자의 인자로 설정한다.
비동기 IO를 만들어보자
비동기 IO를 만들기위해서는 main thread와 분리되어 백그라운드에서 실행될 또 하나의 thread가 필요하다. 즉, IO작업을 할 thread라고 생각하면 된다. 물론 C++에서는 async를 지원할 수 있는 promise가 존재한다. ( future ) 하지만 그냥 쓰면 멋이 없기에 비슷하게 만들어보자.
그럼 위에 제시된 2가지의 문제를 해결해 보자.
먼저 해결하기 위한 요구조건을 나열해보자.
- Logging의 writeFile은 따로 thread를 만들어서 비동기적으로 실행되어야 한다.
- streambuf를 이용하여 custom buffer를 만들고 최대한 write API를 적게 사용하는 방향으로 가야한다.
Logging.h + FileBuffer.h
#include <iostream>
#include <string>
#include <fstream>
#include <unistd.h>
#include <ctime>
#include <memory>
#include <stdexcept>
#include <vector>
#include <thread>
#include <streambuf>
#include <mutex>
#include <condition_variable>
#include <cstring>
#include <queue>
#include <chrono>
#define INFO 1
#define WARNNING 2
#define ERROR 3
#define BUF_SIZE 4096
class FileBuffer : public std::streambuf{
private:
std::ofstream file;
std::thread io_thread;
std::thread timer_thread;
std::mutex mutx;
std::condition_variable condition;
std::string path;
std::char_traits<char>::char_type* buffer = new std::char_traits<char>::char_type[BUF_SIZE]; //stream buffer
std::queue<std::char_traits<char>::char_type*> buffer_queue;
bool ready;
public:
FileBuffer(std::string path);
~FileBuffer();
virtual std::char_traits<char>::int_type overflow(std::char_traits<char>::int_type c);
virtual int sync();
void io_worker();
void timer_worker();
void buffer_init();
void queue_init();
};
class Logging{
private:
std::string path;
std::string GetCurrentPath();
FileBuffer file_buf;
std::ostream async_stream;
void WriteData(std::string msg);
public:
Logging();
void info(std::string msg);
void warning(std::string msg);
void error(std::string msg);
void debug(std::string msg);
~Logging();
};
logging.cpp
#include "main.h"
std::string Logging::GetCurrentPath(){
char temp[1024];
if(getcwd(temp, 1024) != 0){
return std::string(temp);
}
int error = errno;
switch(error){
case EACCES:
throw std::runtime_error("Access denied");
case ENOMEM:
throw std::runtime_error("Insufficient storage");
default: {
throw std::runtime_error("Unrecognised Error");
}
}
}
Logging::Logging() :
file_buf(GetCurrentPath() + "/log.txt"),
async_stream(&file_buf)
{
}
Logging::~Logging(){
}
void Logging::info(std::string msg){
Time time = Time::GetCurrentTime();
std::string str = "[" + Time::ConvertString(time) + "] " + "[INFO]" + " " + msg + "\n";
this->WriteData(str);
}
void Logging::warning(std::string msg){
Time time = Time::GetCurrentTime();
std::string str = "[" + Time::ConvertString(time) + "] " + "[WARNING]" + " " + msg + "\n";
this->WriteData(str);
}
void Logging::error(std::string msg){
Time time = Time::GetCurrentTime();
std::string str = "[" + Time::ConvertString(time) + "] " + "[ERROR]" + " " + msg + "\n";
this->WriteData(str);
}
void Logging::debug(std::string msg){
Time time = Time::GetCurrentTime();
std::string str = "[" + Time::ConvertString(time) + "] " + "[DEBUG]" + " " + msg + "\n";
this->WriteData(str);
}
// file is ofstream
void Logging::WriteData(std::string msg){
this->async_stream << msg;
return;
}
FileBuffer.cpp
#include "main.h"
FileBuffer::FileBuffer(std::string path) :
ready(false),
io_thread(&FileBuffer::io_worker, this),
timer_thread(&FileBuffer::timer_worker, this)
{
buffer = NULL;
this->path = path;
file.open(this->path, std::ios_base::app);
if(!file.is_open()){
throw std::runtime_error(string_format("Unrecognised Error : %d", errno));
}
buffer_init();
}
std::char_traits<char>::int_type FileBuffer::overflow(std::char_traits<char>::int_type c){
if(c != std::char_traits<char>::eof()){
*this->pptr() = std::char_traits<char>::to_char_type(c);
this->pbump(1);
}
{
std::unique_lock<std::mutex> guard(this->mutx);
buffer_queue.push(buffer);
}
buffer_init();
}
void FileBuffer::buffer_init(){
if(buffer != NULL){
buffer = NULL;
}
buffer = new std::char_traits<char>::char_type[BUF_SIZE];
memset(buffer, 0x0, BUF_SIZE);
setp(buffer, buffer+BUF_SIZE-2);
}
int FileBuffer::sync(){
ready = true;
std::unique_lock<std::mutex> guard(this->mutx);
this->condition.notify_one();
return 1;
}
void FileBuffer::io_worker(){
std::char_traits<char>::char_type* tmp_buf;
while(true){
std::unique_lock<std::mutex> guard(this->mutx);
this->condition.wait(guard);
if(!ready){
continue;
}
while(!buffer_queue.empty()){
tmp_buf = buffer_queue.front();
buffer_queue.pop();
file.write(tmp_buf, std::streamsize(std::char_traits<char>::length(tmp_buf)));
delete[] tmp_buf;
}
break;
}
ready = false;
file.flush();
}
void FileBuffer::queue_init(){
while(!buffer_queue.empty()){
std::char_traits<char>::char_type* tmp = buffer_queue.front();
buffer_queue.pop();
delete[] tmp;
}
}
FileBuffer::~FileBuffer(){
if(buffer != NULL){
std::unique_lock<std::mutex> guard(this->mutx);
buffer_queue.push(buffer);
}
sync();
io_thread.join();
timer_thread.join();
queue_init();
}
main.cpp
#include "main.h"
int main(int argc, char** argv){
Logging* logging = new Logging();
logging->info("Booting... System");
logging->info("Good luck overflow!");
logging->warning("Access DataBase");
delete logging;
return 0;
}로직
간단하게 로직을 살펴보자면 main함수에서 logging 클래스를 생성한다.
1. ogging 클래스내에 구현된 info 메소드를 통해서 로그를 기록한다.
- logging.info() 기능을 통해서 ostream에 값을 쓰게 된다.
- 이때 ostream에 있는 buffer는 우리가 만든 FileBuffer이기에 ostream에 값을 쓰게 되면 FileBuffer의 buffer에 값이 쓰여지게 된다.
- buffer에 값이 쓰여지게 되다가 overflow가 된다면 overflow가 되어 담지못한 문자가 EOF인지 확인하고 EOF가 아니라면 해당 버퍼를 1칸 늘리고 해당 문자를 char_type으로 변환 후 buffer에 넣는다.
- 해당 buffer를 Queue에 넣는다. (mutex lock 필요)
- logging class의 소멸자가 작동하게 되면 IO_Thread에 notify_all()하여 깨운다.
- io_thread는 queue를 검사하여 buffer를 write한다.
추가적으로 Timer를 만들어서 10초마다 sync() 메소드를 호출하게 할 수 있지만 귀찮아서 패스
이런식으로 Logging을 Async하게 Write할 수 있다.
이상 끝
Reference
std::basic_ostream<CharT,Traits>::basic_ostream
https://en.cppreference.com/w/cpp/io/basic_ostream/basic_ostream
streambuf
https://docs.microsoft.com/ko-kr/cpp/standard-library/basic-streambuf-class?view=msvc-170
https://stackoverflow.com/questions/25833193/c-how-to-flush-stdstringbuf?rq=1
https://stackoverflow.com/questions/25833193/c-how-to-flush-stdstringbuf?rq=1
