log weekly January 2024 python print logging buffer stdout stdin thread process

print와 logging의 차이 : stdout buffer

2024년 1월 31일 수요일

Today I Learned

날짜

2024년 1월 31일 수요일

내용

logging과 print 문의 차이 : stdout buffer

logging과 print의 차이에 대해 많이 찾아봤는데 디버깅을 위해선 logging문을 쓰는 것이 좋다는 의견이 대다수다. 사실 그냥 다 logging을 쓰라고 한다. 단순 출력이 아닌, 오류 메시지나 변수 내용, 위치 등을 다양하게 출력할 수 있으니 print가 쓰기는 편해도 전체 디버깅 작업의 속도를 높이는데는 logging이 훨씬 효과적이다.

backgrountasks에서 print가 작동이 안되는 이유에 대해선 정확한 내용을 찾기 힘들었는데, stdout buffer가 원인이라는 얘기가 있다.stdout은 표준 출력 데이터를 의미한다. 반대로 stdin은 표준 입력(ex. 키보드) 데이터를 의미한다. 백준에서 알고리즘을 풀다보면 키보드 입력을 input() 이나 sys.stdin.readline() 으로 받곤 하는데 여기서 stdin이 나오는 걸 알 수있다. print 함수는 stdout을 사용하여 출력한다. print문이 콘솔창에 찍히는 것도 표준 출력으로서 나타나는 것.

표준출력은 표시되기 전에 버퍼링된다. 일종의 임시 저장소에 저장되어 처리된다는 의미인데 경우에 따라 이 처리가 늦어지기도 한다. 반면 logging은 표준 출력을 사용하지 않아 곧바로 출력되기 떄문에 멀티스레딩이나 비동기 상황에서도 곧바로 출력된다. 만약 print를 바로 버퍼링없이 바로 출력하고 싶다면 print(”test”, flush=True) 를 사용하면 된다.

1
2
3
4
5
6
7
8
9
10
11

@router.get("/test")
def test(background_tasks: BackgroundTasks):
    background_tasks.add_task(async_backgorund_task, a)
    background_tasks.add_task(async_backgorund_task, b)
    return print("끗")

async def a():
    return print("a", flush=True)

async def b():
    return print("b", flush=True)

실제로 어제와 비슷한 코드로 실험을 해봤다. 함수 a() 와 b() 에서 print에 flush를 넣지 않았을 때는 “끗” 이 출력되고 a,b는 출력되지 않았다. 반면 flush 를 추가해주니 끗 이후 a,b 가 순서대로 출력되었다. 멀티스레드를 이용하는 background_task에서 print문이 작동하지 않는 이유는 버퍼 때문이었다!

이해한 바를 조금 자세히 설명해보자면, backgrountasks는 프로세스 내의 다른 스레드를 이용해 task를 처리하는 시스템이다. 하나의 프로세스 내의 여러 스레드들은 표준출력을 위한 버퍼를 공유한다. 정확히는, 프로세스 내의 여러 리소스들(ex. 메모리)을 공유하는데 표준출력 버퍼도 그 중 하나이다.

background_task는 비동기 작업이기 떄문에 메인스레드와 별도의 생명주기를 가진다. 메인 스레드가 종료되는 것과 무관하게 비동기 스레드(backgroun_task가 처리되는 스레드)는 자신이 처리해야 할 일을 한다. 문제는 프로세스의 종료다. 이 스레드들은 결국 프로세스에 속해있기 떄문에 프로세스가 종료되면 내부의 스레드는 모두 종료되야 한다.

비동기 스레드에서 print문에서 출력할 데이터를 표준출력 버퍼에 저장한다. 이 데이터가 출력되기 위해선, 버퍼가 가득 차 비워주거나 \n이 입력되면 된다. 평소에는 잘 이뤄졌겠지만 멀티스레드 환경에선 조금 다르게 작동한 듯 하다. 프로세스 내의 모든 스레드(메인 스레드, 비동기 스레드, 그 외)가 공유하는 표준 출력 버퍼의 데이터가 처리되기 전에 프로세스가 종료된다면 보통은 버퍼는 초기화된다. 내 경우엔 서버가 지속적으로 작동하고 있기 떄문에 프로세스가 종료되지는 않았으나 버퍼가 비워지도록 처리되지 않아 담겨있는 채 유지되었다. 그리고 다음 요청이 들어와 버퍼에 또 무언가가 채워지면 버퍼가 가득 차 비울 수 있는 조건이 완성되어 비워진다. 이때 출력되어 화면에 나타나게 되는 것 같다.

정리하자면, backgroun_tasks 에서는 print문이 출력되도록 stdout 버퍼를 비우는 조건이 충족되지 않는다는 것이다. 일반적인 경우 프로세스가 종료되거나, 버퍼가 가득 차거나, \n이 입력되면 버퍼가 비워지는데 어떤 원인에서 인지 이 부분이 충족되지 않는 듯 하다. 실제로 flush로 버퍼를 강제로 비우는 로직을 추가한 이후에는 바로 출력되는 걸 보니 맞는 것 같다.

그래서 왜 멀티스레드 환경에서는 버퍼가 비워지지 않는건데? 라고 궁금해졌으나 아직 여기에 대한 답은 찾지 못했다. FastAPI 만든 사람한테 물어봐야하나..

AWS 백서

좁고 얕은 나의 지식이 누군가에게 도움이 되었으면 하는 마음에 AWS 백서를 썼다. 내 지적 수준만큼 아주 짧고 형편없는 내용이다. 그래도 앞으로 1년 후에는 많이 달라져있지 않을까 하는 마음에 썼으니 열심히 공부해서 점차 퀄리티를 높여갈 예정.

회고

오랜만에 CS 내용을 보니 여전히 어렵다. 전공 좀 잘 고를껄.

CATALOG
    weekly