скрытое меню

логгирование : как раскрутить логику работы программы

Пора поделится действительно удобным способом логгирование выполнения программы. Создаем например файл myDebug.h . Добавляем в него следующие макросы :


#define t1 "\t"
#define t2 "\t\t"
#define t3 "\t\t\t"
#define t4 "\t\t\t\t"
#define t5 "\t\t\t\t\t"
#define t6 "\t\t\t\t\t\t"
#define t7 "\t\t\t\t\t\t\t"
#define t8 "\t\t\t\t\t\t\t\t"
#define t9 "\t\t\t\t\t\t\t\t\t"
#define t10 "\t\t\t\t\t\t\t\t\t\t"

extern volatile uint32_t LEFT_MARGIN;

#define PRINTF_LEFT(num) for( uint8_t ii = 0 ; ii < num ; ii++ ){ \
	printf(" "); }

#define PRINTF_FILL(num,str) for( uint8_t ii = 0 ; ii < num ; ii++ ){ \
	printf("%s",str); }

#define PRINTF(num,message)  PRINTF_LEFT(num); \
	printf message

#define DEBUG_FUNC_CALLS 1

#ifdef DEBUG_FUNC_CALLS

	#define PRINTF123(filter,message) { \
			PRINTF(0,("%d : " , xTaskGetTickCount())); \
			PRINTF_FILL(LEFT_MARGIN<<2," ");\
			PRINTF(3,message);  \
			}

	#define ENTER_FUNC(name) { \
			taskENTER_CRITICAL(); \
			LEFT_MARGIN ++; \
			PRINTF(0,("%d : " , xTaskGetTickCount())); \
			PRINTF_FILL(LEFT_MARGIN<<2,"-");\
			printf(" > %s\n",name); \
			taskEXIT_CRITICAL(); \
			}

	#define EXIT_FUNC(name) { \
			taskENTER_CRITICAL(); \
			PRINTF(0,("%d : " , xTaskGetTickCount())); \
			if(LEFT_MARGIN==0) { \
				PRINTF(LEFT_MARGIN,("stop LEFT_MARGIN=%d" , LEFT_MARGIN)); \
				PRINTF(0,("\n")); \
				while(1) ; \
			} \
			PRINTF_FILL(LEFT_MARGIN<<2,"-");\
			printf(" < %s\n",name); \
			LEFT_MARGIN--; \
			taskEXIT_CRITICAL(); \
			}

#else
	#define ENTER_FUNC(name)
	#define EXIT_FUNC(name)
	#define PRINTF123(filter,message)
#endif

Создаем myDebug.с .

#include "stdio.h"
volatile uint32_t LEFT_MARGIN = 0;

Далее во все важные функции добавляем в начале ENTER_FUNC( __func__ ); . В конце (на выходе) и также перед каждым return EXIT_FUNC( __func__ );. И везде где надо PRINTF123(..)

Не забываем #include "myDebug.h" в начале файлов с анализируемыми функциями.

static struct pbuf * tcp_output_alloc_header ( struct tcp_pcb *pcb , u16_t optlen , u16_t datalen ,
		u32_t seqno_be /* already in network byte order */)
{
	ENTER_FUNC( __func__ );

	struct tcp_hdr *tcphdr;
	struct pbuf *p = pbuf_alloc ( PBUF_IP , TCP_HLEN + optlen + datalen , PBUF_RAM );

	if ( p != NULL )
	{
		LWIP_ASSERT( "check that first pbuf can hold struct tcp_hdr" , (p->len >= TCP_HLEN + optlen) );

		tcphdr = ( struct tcp_hdr * ) p->payload;
		tcphdr->src = htons( pcb->local_port );
		tcphdr->dest = htons( pcb->remote_port );
		tcphdr->seqno = seqno_be;
		tcphdr->ackno = htonl( pcb->rcv_nxt );
		TCPH_HDRLEN_FLAGS_SET( tcphdr , ( 5 + optlen / 4 ) , TCP_ACK );
		tcphdr->wnd = htons( pcb->rcv_ann_wnd );
		tcphdr->chksum = 0;
		tcphdr->urgp = 0;

		/* If we're sending a packet, update the announced right window edge */
		PRINTF123( FUNC_CALLS , (t1"pcb->rcv_nxt %u [%u] (uint32_t )pcb->rcv_ann_wnd %u\n" ,
				pcb->rcv_nxt , fine_seqno(pcb->rcv_nxt) , (uint32_t )pcb->rcv_ann_wnd));

		pcb->rcv_ann_right_edge = pcb->rcv_nxt + (uint32_t )pcb->rcv_ann_wnd;

		PRINTF123( FUNC_CALLS , (t1"pcb->rcv_ann_right_edge = pcb->rcv_nxt + pcb->rcv_ann_wnd = %u [%u]\n" ,
				pcb->rcv_ann_right_edge,fine_seqno(pcb->rcv_ann_right_edge)));
	}

	EXIT_FUNC( __func__ );
	return p;
}

И получаем результат выполнения программы красиво с отступами , все видно - вложенности вызовов. Просто красота для анализа.


20808 : ---------------- > tcp_output
20808 :                    tcp_output: snd_wnd 64240, cwnd 2920, wnd 2920, effwnd 238, seq 6549, ack 6549
20809 : -------------------- > tcp_output_segment
20809 :                        tcp_output_segment: rtseq 6549
20809 :                        tcp_output_segment: 6549:6787
20809 :                        TCP header:
20810 :                        +-------------------------------+
20810 :                        |       80      |    64576      | (src port, dest port)
20810 :                        +-------------------------------+
20810 :                        |           0000006549          | (seq no) [1781728411]
20811 :                        +-------------------------------+
20811 :                        |           2513251606          | (ack no) [6172]
20811 :                        +-------------------------------+
20812 :                        |  5 |   |011001|      4048     | (hdrlen, flags (FIN PSH ACK ), win)
20812 :                        +-------------------------------+
20812 :                        |    0x91ea     |         0     | (chksum, urgp)
20813 :                        +-------------------------------+
20813 : ------------------------ > ip_output
20813 : ---------------------------- > ip_output_if
20813 : -------------------------------- > pbuf_header
20813 :                                    pbuf_header: old 2000B188 new 2000B174 (20)
20814 : -------------------------------- < pbuf_header
20814 : -------------------------------- > rndis_output_fn
20814 : ------------------------------------ > etharp_output
20814 : ---------------------------------------- > pbuf_header
20815 :                                            pbuf_header: old 2000B174 new 2000B166 (14)
20815 : ---------------------------------------- < pbuf_header
20815 : ---------------------------------------- > etharp_output_to_arp_index
20816 : -------------------------------------------- > etharp_send_ip
20816 :                                                etharp_send_ip: sending packet 0x2000b154
20816 : ------------------------------------------------ > rndis_linkoutput_fn
20817 : ---------------------------------------------------- > rndis_can_send
20817 : ---------------------------------------------------- < rndis_can_send
20817 : ---------------------------------------------------- > rndis_can_send
20818 : ---------------------------------------------------- < rndis_can_send
20818 : ---------------------------------------------------- > rndis_send

 send : 
 0x20 0x89 0x84 0x6A 0x96 0xAA 0x20 0x89 0x84 0x6A 0x96 0x03 0x08 0x00 0x45 0x00 0x01 0x16 0x00 0x05 0x00 0x00 0x1C 0x06 0x0E 0x89 0xC0 0xA8 0x07 0x01 0xC0 0xA8 0x07 0x03 0x00 0x50 0xFC 0x40 0x00 0x00 0x19 0x95 0x95 0xCD 0x2D 0x16 0x50 0x19 0x0F 0xD0 0x91 0xEA 0x00 0x00 0x48 0x54 0x54 0x50 0x2F 0x31 0x2E 0x30 0x20 0x34 0x30 0x34 0x20 0x46 0x69 0x6C 0x65 0x20 0x6E 0x6F 0x74 0x20 0x66 0x6F 0x75 0x6E 0x64 0x0D 0x0A 0x53 0x65 0x72 0x76 0x65 0x72 0x3A 0x20 0x6C 0x77 0x49 0x50 0x2F 0x31 0x2E 0x33 0x2E 0x31 0x20 0x28 0x68 0x74 0x74 0x70 0x3A 0x2F 0x2F 0x73 0x61 0x76 0x61 0x6E 0x6E 0x61 0x68 0x2E 0x6E 0x6F 0x6E 0x67 0x6E 0x75 0x2E 0x6F 0x72 0x67 0x2F 0x70 0x72 0x6F 0x6A 0x65 0x63 0x74 0x73 0x2F 0x6C 0x77 0x69 0x70 0x29 0x0D 0x0A 0x43 0x6F 0x6E 0x74 0x65 0x6E 0x74 0x2D 0x74 0x79 0x70 0x65 0x3A 0x20 0x74 0x65 0x78 0x74 0x2F 0x68 0x74 0x6D 0x6C 0x0D 0x0A 0x0D 0x0A 0x3C 0x68 0x74 0x6D 0x6C 0x3E 0x0A 0x3C 0x68 0x65 0x61 0x64 0x3E 0x3C 0x74 0x69 0x74 0x6C 0x65 0x3E 0x45 0x78 0x61 0x6D 0x70 0x6C 0x65 0x3C 0x2F 0x74 0x69 0x74 0x6C 0x65 0x3E 0x3C 0x2F 0x68 0x65 0x61 0x64 0x3E 0x0A 0x3C 0x62 0x6F 0x64 0x79 0x20 0x62 0x67 0x63 0x6F 0x6C 0x6F 0x72 0x3D 0x22 0x77 0x68 0x69 0x74 0x65 0x22 0x20 0x74 0x65 0x78 0x74 0x3D 0x22 0x62 0x6C 0x61 0x63 0x6B 0x22 0x3E 0x0A 0x3C 0x48 0x31 0x3E
 0x50 0x41 0x47 0x45 0x20 0x4E 0x4F 0x54 0x20 0x46 0x4F 0x55 0x4E 0x44 0x3C 0x2F 0x48 0x31 0x3E 0x0A 0x3C 0x2F 0x62 0x6F 0x64 0x79 0x3E 0x0A 0x3C 0x2F 0x68 0x74 0x6D 0x6C 0x3E 0x0A
20826 : ---------------------------------------------------- < rndis_send
20826 : ------------------------------------------------ < rndis_linkoutput_fn
20827 : -------------------------------------------- < etharp_send_ip
20827 : ---------------------------------------- < etharp_output_to_arp_index
20828 : ------------------------------------ < etharp_output
20828 : -------------------------------- < rndis_output_fn
20828 : ---------------------------- < ip_output_if
20829 : ------------------------ < ip_output
20829 : -------------------- < tcp_output_segment
20829 : ---------------- < tcp_output
20829 :                TCP State: FIN_WAIT_1
20829 : ------------ < tcp_input
20829 : -------- < ip_input
20829 : ---- < ethernet_input
2083

Именно этот подход выручил при анализе отработки post запроса не сервере под контроллером STM32F205 .