Cộng đồng Hỏi & Đáp của Inflearn

안녕하세요. 박상우님!
멀티태스킹 환경에서의 printf 디버깅은 자칫하면 태스크의 동작 상황에 대해 잘못 이해하는 오류를 범하기 쉬운데요. 그런 의미에서 지금 하신 질문과 궁금증은 그 의미가 크다고 할 수 있습니다.
답변 드리기 앞서 제가 수행한 테스트와 그 결과를 지금부터 봐주시죠.
테스트에 사용한 코드는 다음과 같습니다. 박상우님이 궁금해 하시는 그 조건이죠.
저는 로직분석기를 이용해서 태스크 동작을 면밀히 보기 위해 필요한 코드를 추가하였습니다.
HAL_GPIO_WritePin(GPIOB, T1_Pin, GPIO_PIN_SET); 바로 이거입니다.

static void Task1( void const *pvParameters )
{
	const char *pcTaskName = "Task1";

	pvParameters = pvParameters; // for compiler warning

	/* Print out the name of this task. */
	printf( "%s is running\n", pcTaskName );

	printf("\n-------  Task1 information -------\n");
	printf("task1 name = %s \n",pcTaskGetName( xHandle1 ));
	printf("task1 priority = %d \n",(int)uxTaskPriorityGet( xHandle1 ));
//	printf("task1 status = %d \n",eTaskGetState( xHandle1 ));
	printf("----------------------------------\n");
	//vTaskDelay(1);
	while(1) {
		  HAL_GPIO_WritePin(GPIOB, T1_Pin, GPIO_PIN_SET);

	/* TODO #3:
		코드를 실행 하여 보고
		vTaskDelay() 코드를 주석 처리한 후 그 결과를 설명한다 */
#if 1 // No comment
//vTaskDelay (pdMS_TO_TICKS (1000));
printf("a"); fflush(stdout);	// 문자 'a' 출력
#endif // TODO #3
HAL_GPIO_WritePin(GPIOB, T1_Pin, GPIO_PIN_SET);

		task1timer++;
	}
}

static void Task2( const struct Param_types *Param )
{
	const char *pcTaskName = "Task2";

	/* Print out the name of this task. */
	printf( "%s is running\n", pcTaskName );

	printf("\n-------  Task2 parameter passed from main --------\n");
	printf("task2 first parameter = %d \n",Param->P1);
	printf("task2 second parameter = %d \n",Param->P2);
	printf("--------------------------------------------------\n");

	while(1) {
		HAL_GPIO_WritePin(GPIOB, T2_Pin, GPIO_PIN_SET);

		int i;
	/* TODO #3:
		코드를 실행 하여 보고
		vTaskDelay() 코드를 주석 처리한 후 그 결과를 설명한다 */

#if 1 // No comment
//vTaskDelay (pdMS_TO_TICKS (1000));
printf("b"); fflush(stdout);	// 문자 'b' 출력
#endif // TODO #3
		HAL_GPIO_WritePin(GPIOB, T2_Pin, GPIO_PIN_SET);

		task2timer++;
	}
}

아래 실행결과를 보시죠. 정확하게 우선순위를 동일하게 부여한 Task1 와 Task2 은 printf, fflush, HAL_UART_Transmit 가 실행되고 있는지 여부와 관계없이 정확하게 1밀리 초 간격으로 라운드로빈이 수행되는 것을 볼 수 있습니다.

또한 아래와 같은 테스트 결과도 보시겠습니다. 단지 171 라인의 실행 유무에 따라 아래와 같이 printf 출력 결과는 크게 달라집니다.

이 증상은 어떻게 설명할 수 있는가 하면 규칙적으로 발생하는 tick 인터럽트와 주기적(일정한 간격)으로 실행되는 for 루프를 고려하면 어떤 태스크는 운이좋아 콘솔 출력버퍼에 글자를 더 많이 입력할 수 있게 되고 또 다른 어떤 태스크는 콘솔 출력버퍼에 글자를 덜 입력하게 되는 상황으로 이해할 수 있을 겁니다.

아래 함수 HAL_UART_Transmit 내에서는 UART 전송을 위해 버퍼가 비워지는 때까지 CPU 시간을 소모하면서 기다리는 코드(UART_WaitOnFlagUntilTimeout) 가 사용되고 있는데, 이 함수가 바로 지금 이러한 이상한 일이 일어나는 주 원인일 것입니다. 절묘한 타이밍 차이에 따라 task1 이나 task2 둘 중 하나는 이 쓸모없는? 일만 수행하게 되었을 겁니다. 어떤 태스크는 a (혹은 b) 글자를 버퍼에 넣는 생산적인 일을 위주로 실행하는가 하면, 어떤 태스크는 이 기다리는 일을 위주로 수행 하는 거죠.

HAL_StatusTypeDef HAL_UART_Transmit(UART_HandleTypeDef *huart, uint8_t *pData, uint16_t Size, uint32_t Timeout)
{
  uint8_t  *pdata8bits;
  uint16_t *pdata16bits;
  uint32_t tickstart = 0U;

  /* Check that a Tx process is not already ongoing */
  if (huart->gState == HAL_UART_STATE_READY)
  {
    if ((pData == NULL) || (Size == 0U))
    {
      return  HAL_ERROR;
    }

    /* Process Locked */
    __HAL_LOCK(huart);

    huart->ErrorCode = HAL_UART_ERROR_NONE;
    huart->gState = HAL_UART_STATE_BUSY_TX;

    /* Init tickstart for timeout management */
    tickstart = HAL_GetTick();

    huart->TxXferSize = Size;
    huart->TxXferCount = Size;

    /* In case of 9bits/No Parity transfer, pData needs to be handled as a uint16_t pointer */
    if ((huart->Init.WordLength == UART_WORDLENGTH_9B) && (huart->Init.Parity == UART_PARITY_NONE))
    {
      pdata8bits  = NULL;
      pdata16bits = (uint16_t *) pData;
    }
    else
    {
      pdata8bits  = pData;
      pdata16bits = NULL;
    }

    /* Process Unlocked */
    __HAL_UNLOCK(huart);

    while (huart->TxXferCount > 0U)
    {
      if (UART_WaitOnFlagUntilTimeout(huart, UART_FLAG_TXE, RESET, tickstart, Timeout) != HAL_OK)
      {
        return HAL_TIMEOUT;
      }
      if (pdata8bits == NULL)
      {
        huart->Instance->DR = (uint16_t)(*pdata16bits & 0x01FFU);
        pdata16bits++;
      }
      else
      {
        huart->Instance->DR = (uint8_t)(*pdata8bits & 0xFFU);
        pdata8bits++;
      }
      huart->TxXferCount--;
    }

    if (UART_WaitOnFlagUntilTimeout(huart, UART_FLAG_TC, RESET, tickstart, Timeout) != HAL_OK)
    {
      return HAL_TIMEOUT;
    }

    /* At end of Tx process, restore huart->gState to Ready */
    huart->gState = HAL_UART_STATE_READY;

    return HAL_OK;
  }
  else
  {
    return HAL_BUSY;
  }
}

따라서, 개발과 디버깅에 있어 언제든 이런 상황이 일어나고 있다는 점을 고려해야 할겁니다.

그리고, 추가적으로 아래 소스도 참고해보시기 바랍니다.

### 1. printf.c
https://github.com/lattera/glibc/blob/master/stdio-common/printf.c

### 2. vfprintf.c

https://github.com/lattera/glibc/blob/master/stdio-common/vfprintf.c

### 3. fileops.c (new_do_write, IOnew_file_write 등)

https://github.com/lattera/glibc/blob/master/libio/fileops.c

https://github.com/bminor/glibc/blob/master/libio/fileops.c

### 4. syscall.S (x86_64 어셈블리)

https://github.com/lattera/glibc/blob/master/sysdeps/unix/sysv/linux/x86_64/syscall.S

### 5. iofflush.c

https://github.com/lattera/glibc/blob/master/libio/iofflush.c

안녕하세요, 인프런 AI 인턴입니다.

박상우님께서 문의하신 내용 관련하여, fflush 함수가 실행 시 영향을 미치는 상황에 대해 설명드리겠습니다.

실행 흐름 분석:

1. Task 우선순위: Task1과 Task2는 동일 우선순위를 가지고 있으며, 라운드 로빈 방식으로 CPU 시간을 배분받습니다. 이는 각각의 Task가 동일한 실행 시간을 받게 된다는 것을 의미합니다.

2. 버퍼 및 fflush의 영향: fflush 함수는 출력 버퍼를 강제로 비우고, 이는 즉각적인 출력 장치로의 전송을 일으킵니다. 특이점은, 이 버퍼 전송 과정에서 UART나 다른 I/O 장치에 병목이 발생할 수 있다는 것입니다. 특히 UART는 상대적으로 느리기 때문에, 한 번의 전송에 상당한 시간이 소요될 수 있습니다.

3. fflush에 따른 출력 불균형: 이러한 환경에서, Task1이나 Task2 중 하나가 상대적으로 무거운 I/O 작업을 수행하게 되면, 해당 Task는 자주 실행되지 못하고, 다른 Task는 그 사이에 더 많이 실행될 수 있습니다. 결과적으로, “aaaaaaaaaaab”처럼 a가 많이 출력된 후 b가 출력되는 패턴이 나타날 수 있습니다. 이는 Task1이 fflush 호출시 전송률에 영향을 받아 상대적으로 적은 시간이 소요되는 동안, Task2는 다른 일이 없기 때문에 더 빠르게 돌아갈 수 있기 때문입니다.

관련하여 더 깊이 이해하고 싶으시다면, 아래의 답변 링크들을 참고하시면 도움이 될 것입니다:

• 섹션 4 <소스코드 분석 - printf, fflush> 관련 질문
  
• fflush질문
  

제가 제공한 설명이 문제 해결에 도움이 되었길 희망합니다.

저는 질문자님의 이해를 돕고자 지식공유자님의 기존 답변을 참고하여 유사한 답변 링크를 추천해드리고 있습니다.
현재 베타 기능으로 답변이 만족스럽지 않을 수 있는 점 양해 부탁드립니다. 🙏
추가적으로 궁금한 점이 있으시면, 이어서 질문해 주세요. 곧 지식공유자께서 답변해 주실 것입니다.