漫談android系統(7)-log系統1

前言

羅升陽的《Android系統源代碼情景分析》一書，有關log是如何顯示，那麼真的在代碼中是如何實現的呢？就該問題我想需要細細分析

bootloader層的log

在firmware中的log是如何產生的，我沒有看過firmware的code,不清楚它是如何實現的，這是我的短板，回頭得補上！在這裡先分析lk中是如何實現的。

從aboot.c著手

相信在源碼中看到bootable\bootloader\lk下的app\aboot.c中最常用於打log信息的語句為dprintf。那麼它的原型在哪裡？

其原型非常好找，在lk\include\debug.h中就有定義。

/* debug levels */
#define CRITICAL 0
#define ALWAYS 0
#define INFO 1
#define SPEW 2

/* output */
void _dputc(char c); // XXX for now, platform implements
int _dputs(const char *str);
int _dprintf(const char *fmt, ...) __PRINTFLIKE(1, 2);
int _dvprintf(const char *fmt, va_list ap);

#define dputc(level, str) do { if ((level) <= DEBUGLEVEL) { _dputc(str); } } while (0)
#define dputs(level, str) do { if ((level) <= DEBUGLEVEL) { _dputs(str); } } while (0)
#define dprintf(level, x...) do { if ((level) <= DEBUGLEVEL) { _dprintf(x); } } while (0)
#define dvprintf(level, x...) do { if ((level) <= DEBUGLEVEL) { _dvprintf(x); } } while (0)

宏定義dprintf(level, x…)讓我們可以看到其實際調用的還是 _dprintf(x),然後我們去定位到lk\platform\msm_share\debug.c

int _dprintf(const char *fmt, ...)
{
    char buf[256];
    char ts_buf[13];
    int err;

    snprintf(ts_buf, sizeof(ts_buf), "[%u] ",(unsigned int)current_time());
    dputs(ALWAYS, ts_buf);

    va_list ap;
    va_start(ap, fmt);
    err = vsnprintf(buf, sizeof(buf), fmt, ap);
    va_end(ap);

    dputs(ALWAYS, buf);

    return err;
}

因而不難看出它最後是將buf組成後扔給dputs。看前面有宏定義dputs

int _dputs(const char *str)
{
    while(*str != 0) {
        _dputc(*str++);
    }

    return 0;
}
//
void _dputc(char c)
{
#if WITH_DEBUG_LOG_BUF
    log_putc(c);
#endif
#if WITH_DEBUG_DCC
    if (c == '\n') {
        write_dcc('\r');
    }
    write_dcc(c) ;
#endif
#if WITH_DEBUG_UART
    uart_putc(0, c);
#endif
#if WITH_DEBUG_FBCON && WITH_DEV_FBCON
    fbcon_putc(c);
#endif
#if WITH_DEBUG_JTAG
    jtag_dputc(c);
#endif
}

在這裡，我表示追捕不到WITH_DEBUG_UART的宏是如何定義的，如果有知道的朋友，歡迎留言幫我解決這個問題。

我猜想應該是使用WITH_DEBUG_UART這個宏

這樣我們可以去找到uart_putc的實現方法，然後逐層分析。可以定位到lk\platform\msm_share\uart_dm.c

/* UART_DM uses four character word FIFO where as UART core
 * uses a character FIFO. so it's really inefficient to try
 * to write single character. But that's how dprintf has been
 * implemented.
 */
int uart_putc(int port, char c)
{
    uint32_t uart_base = port_lookup[port];

    /* Don't do anything if UART is not initialized */
    if (!uart_init_flag)
        return -1;

    msm_boot_uart_dm_write(uart_base, &c, 1);

    return 0;
}

msm_boot_uart_dm_write(uint32_t base, char *data, unsigned int num_of_chars)
{
    unsigned int tx_word_count = 0;
    unsigned int tx_char_left = 0, tx_char = 0;
    unsigned int tx_word = 0;
    int i = 0;
    char *tx_data = NULL;
    uint8_t num_chars_written;

    if ((data == NULL) || (num_of_chars <= 0)) {
        return MSM_BOOT_UART_DM_E_INVAL;
    }

    msm_boot_uart_calculate_num_chars_to_write(data, &num_of_chars);

    tx_data = data;

    /* Write to NO_CHARS_FOR_TX register number of characters
     * to be transmitted. However, before writing TX_FIFO must
     * be empty as indicated by TX_READY interrupt in IMR register
     */

    /* Check if transmit FIFO is empty.
     * If not we'll wait for TX_READY interrupt. */
    if (!(readl(MSM_BOOT_UART_DM_SR(base)) & MSM_BOOT_UART_DM_SR_TXEMT)) {
        while (!(readl(MSM_BOOT_UART_DM_ISR(base)) & MSM_BOOT_UART_DM_TX_READY)) {
            udelay(1);
            /* Kick watchdog? */
        }
    }

    //We need to make sure the DM_NO_CHARS_FOR_TX&DM_TF are are programmed atmoically.
    enter_critical_section();
    /* We are here. FIFO is ready to be written. */
    /* Write number of characters to be written */
    writel(num_of_chars, MSM_BOOT_UART_DM_NO_CHARS_FOR_TX(base));

    /* Clear TX_READY interrupt */
    writel(MSM_BOOT_UART_DM_GCMD_RES_TX_RDY_INT, MSM_BOOT_UART_DM_CR(base));

    /* We use four-character word FIFO. So we need to divide data into
     * four characters and write in UART_DM_TF register */
    tx_word_count = (num_of_chars % 4) ? ((num_of_chars / 4) + 1) :
        (num_of_chars / 4);
    tx_char_left = num_of_chars;

    for (i = 0; i < (int)tx_word_count; i++) {
        tx_char = (tx_char_left < 4) ? tx_char_left : 4;
        num_chars_written = pack_chars_into_words((uint8_t *)tx_data, tx_char, &tx_word);

        /* Wait till TX FIFO has space */
        while (!(readl(MSM_BOOT_UART_DM_SR(base)) & MSM_BOOT_UART_DM_SR_TXRDY)) {
            udelay(1);
        }

        /* TX FIFO has space. Write the chars */
        writel(tx_word, MSM_BOOT_UART_DM_TF(base, 0));
        tx_char_left = num_of_chars - (i + 1) * 4;
        tx_data = tx_data + num_chars_written;
    }
    exit_critical_section();

    return MSM_BOOT_UART_DM_E_SUCCESS;
}

在這裡的code明顯看出是否初始化uart成功，然後調用msm_boot_uart_dm_write函數，驗證輸入字符，檢查fifo隊列是否已經清空數據，重置tx中斷，寫入相關的寄存器，等等，在這裡我不詳細解釋了，可以慢慢看code，細細體會其中神奇的地方。

//驗證輸入字符自動加\n
/*
 * Helper function to keep track of Line Feed char "\n" with
 * Carriage Return "\r\n".
 */
static unsigned int
msm_boot_uart_calculate_num_chars_to_write(char *data_in,
                uint32_t *num_of_chars)
{
    uint32_t i = 0, j = 0;

    if ((data_in == NULL)) {
        return MSM_BOOT_UART_DM_E_INVAL;
    }

    for (i = 0, j = 0; i < *num_of_chars; i++, j++) {
        if (data_in[i] == '\n') {
            j++;
        }

    }

    *num_of_chars = j;

    return MSM_BOOT_UART_DM_E_SUCCESS;
}

其實在這裡我們僅僅只是對發送log做了解析。對於我們在終端可以向機台發送命令，其機制也有，其基本與發送的機制一樣。

/* UART_DM uses four character word FIFO whereas uart_getc
 * is supposed to read only one character. So we need to
 * read a word and keep track of each character in the word.
 */
int uart_getc(int port, bool wait)
{
    int byte;
    static unsigned int word = 0;
    uint32_t uart_base = port_lookup[port];

    /* Don't do anything if UART is not initialized */
    if (!uart_init_flag)
        return -1;

    if (!word) {
        /* Read from FIFO only if it's a first read or all the four
         * characters out of a word have been read */
        if (msm_boot_uart_dm_read(uart_base, &word, wait) != MSM_BOOT_UART_DM_E_SUCCESS) {
            return -1;
        }

    }

    byte = (int)word & 0xff;
    word = word >> 8;

    return byte;
}
/*
 * UART Receive operation
 * Reads a word from the RX FIFO.
 */
static unsigned int
msm_boot_uart_dm_read(uint32_t base, unsigned int *data, int wait)
{
    static int rx_last_snap_count = 0;
    static int rx_chars_read_since_last_xfer = 0;

    if (data == NULL) {
        return MSM_BOOT_UART_DM_E_INVAL;
    }

    /* We will be polling RXRDY status bit */
    while (!(readl(MSM_BOOT_UART_DM_SR(base)) & MSM_BOOT_UART_DM_SR_RXRDY)) {
        /* if this is not a blocking call, we'll just return */
        if (!wait) {
            return MSM_BOOT_UART_DM_E_RX_NOT_READY;
        }
    }

    /* Check for Overrun error. We'll just reset Error Status */
    if (readl(MSM_BOOT_UART_DM_SR(base)) & MSM_BOOT_UART_DM_SR_UART_OVERRUN) {
        writel(MSM_BOOT_UART_DM_CMD_RESET_ERR_STAT, MSM_BOOT_UART_DM_CR(base));
    }

    /* RX FIFO is ready; read a word. */
    *data = readl(MSM_BOOT_UART_DM_RF(base, 0));

    /* increment the total count of chars we've read so far */
    rx_chars_read_since_last_xfer += 4;

    /* Rx transfer ends when one of the conditions is met:
     * - The number of characters received since the end of the previous
     *   xfer equals the value written to DMRX at Transfer Initialization
     * - A stale event occurred
     */

    /* If RX transfer has not ended yet */
    if (rx_last_snap_count == 0) {
        /* Check if we've received stale event */
        if (readl(MSM_BOOT_UART_DM_MISR(base)) & MSM_BOOT_UART_DM_RXSTALE) {
            /* Send command to reset stale interrupt */
            writel(MSM_BOOT_UART_DM_CMD_RES_STALE_INT, MSM_BOOT_UART_DM_CR(base));
        }

        /* Check if we haven't read more than DMRX value */
        else if ((unsigned int)rx_chars_read_since_last_xfer <
            readl(MSM_BOOT_UART_DM_DMRX(base))) {
            /* We can still continue reading before initializing RX transfer */
            return MSM_BOOT_UART_DM_E_SUCCESS;
        }

        /* If we've reached here it means RX
         * xfer end conditions been met
         */

        /* Read UART_DM_RX_TOTAL_SNAP register
         * to know how many valid chars
         * we've read so far since last transfer
         */
        rx_last_snap_count = readl(MSM_BOOT_UART_DM_RX_TOTAL_SNAP(base));

    }

    /* If there are still data left in FIFO we'll read them before
     * initializing RX Transfer again */
    if ((rx_last_snap_count - rx_chars_read_since_last_xfer) >= 0) {
        return MSM_BOOT_UART_DM_E_SUCCESS;
    }

    msm_boot_uart_dm_init_rx_transfer(base);
    rx_last_snap_count = 0;
    rx_chars_read_since_last_xfer = 0;

    return MSM_BOOT_UART_DM_E_SUCCESS;
}

了解uart是如何初始化的

還記得有一文中有講到如何進行lk的啟動的，在kmain(void)函數中會調用target_early_init()此時就是對uart的寄存器做了初始化。

void target_early_init(void)
{
#if WITH_DEBUG_UART
    uart_dm_init(1, 0, BLSP1_UART0_BASE);
#endif
}

而uart_dm_init函數就是對uart的初始化動作

/* Defining functions that's exposed to outside world and in coformance to
 * existing uart implemention. These functions are being called to initialize
 * UART and print debug messages in bootloader.
 */
void uart_dm_init(uint8_t id, uint32_t gsbi_base, uint32_t uart_dm_base)
{
    static uint8_t port = 0;
    char *data = "Android Bootloader - UART_DM Initialized!!!\n";

    /* Configure the uart clock */
    clock_config_uart_dm(id);
    dsb();

    /* Configure GPIO to provide connectivity between UART block
       product ports and chip pads */
    gpio_config_uart_dm(id);
    dsb();

    /* Configure GSBI for UART_DM protocol.
     * I2C on 2 ports, UART (without HS flow control) on the other 2.
     * This is only on chips that have GSBI block
     */
     if(gsbi_base)
        writel(GSBI_PROTOCOL_CODE_I2C_UART <<
            GSBI_CTRL_REG_PROTOCOL_CODE_S,
            GSBI_CTRL_REG(gsbi_base));
    dsb();

    /* Configure clock selection register for tx and rx rates.
     * Selecting 115.2k for both RX and TX.
     */
    writel(UART_DM_CLK_RX_TX_BIT_RATE, MSM_BOOT_UART_DM_CSR(uart_dm_base));
    dsb();

    /* Intialize UART_DM */
    msm_boot_uart_dm_init(uart_dm_base);

    msm_boot_uart_dm_write(uart_dm_base, data, 44);

    ASSERT(port < ARRAY_SIZE(port_lookup));
    port_lookup[port++] = uart_dm_base;

    /* Set UART init flag */
    uart_init_flag = 1;
}

因而我們可以看到uart初始化時鐘後，設定gpio,設置頻率，設置寄存器，設置flag。

/* Configure UART clock based on the UART block id*/
void clock_config_uart_dm(uint8_t id)
{
    int ret;
    char iclk[64];
    char cclk[64];

    snprintf(iclk, sizeof(iclk), "uart%u_iface_clk", id);
    snprintf(cclk, sizeof(cclk), "uart%u_core_clk", id);

    ret = clk_get_set_enable(iclk, 0, 1);
    if(ret)
    {
        dprintf(CRITICAL, "failed to set %s ret = %d\n", iclk, ret);
        ASSERT(0);
    }

    ret = clk_get_set_enable(cclk, 7372800, 1);
    if(ret)
    {
        dprintf(CRITICAL, "failed to set %s ret = %d\n", cclk, ret);
        ASSERT(0);
    }
}

/* Configure gpio for blsp uart 2 */
void gpio_config_uart_dm(uint8_t id)
{
    /* configure rx gpio */
    gpio_tlmm_config(5, 2, GPIO_INPUT, GPIO_NO_PULL,
                GPIO_8MA, GPIO_DISABLE);

    /* configure tx gpio */
    gpio_tlmm_config(4, 2, GPIO_OUTPUT, GPIO_NO_PULL,
                GPIO_8MA, GPIO_DISABLE);
}

/*
 * Initialize UART_DM - configure clock and required registers.
 */
static unsigned int msm_boot_uart_dm_init(uint32_t uart_dm_base)
{
    /* Configure UART mode registers MR1 and MR2 */
    /* Hardware flow control isn't supported */
    writel(0x0, MSM_BOOT_UART_DM_MR1(uart_dm_base));

    /* 8-N-1 configuration: 8 data bits - No parity - 1 stop bit */
    writel(MSM_BOOT_UART_DM_8_N_1_MODE, MSM_BOOT_UART_DM_MR2(uart_dm_base));

    /* Configure Interrupt Mask register IMR */
    writel(MSM_BOOT_UART_DM_IMR_ENABLED, MSM_BOOT_UART_DM_IMR(uart_dm_base));

    /* Configure Tx and Rx watermarks configuration registers */
    /* TX watermark value is set to 0 - interrupt is generated when
     * FIFO level is less than or equal to 0 */
    writel(MSM_BOOT_UART_DM_TFW_VALUE, MSM_BOOT_UART_DM_TFWR(uart_dm_base));

    /* RX watermark value */
    writel(MSM_BOOT_UART_DM_RFW_VALUE, MSM_BOOT_UART_DM_RFWR(uart_dm_base));

    /* Configure Interrupt Programming Register */
    /* Set initial Stale timeout value */
    writel(MSM_BOOT_UART_DM_STALE_TIMEOUT_LSB, MSM_BOOT_UART_DM_IPR(uart_dm_base));

    /* Configure IRDA if required */
    /* Disabling IRDA mode */
    writel(0x0, MSM_BOOT_UART_DM_IRDA(uart_dm_base));

    /* Configure and enable sim interface if required */

    /* Configure hunt character value in HCR register */
    /* Keep it in reset state */
    writel(0x0, MSM_BOOT_UART_DM_HCR(uart_dm_base));

    /* Configure Rx FIFO base address */
    /* Both TX/RX shares same SRAM and default is half-n-half.
     * Sticking with default value now.
     * As such RAM size is (2^RAM_ADDR_WIDTH, 32-bit entries).
     * We have found RAM_ADDR_WIDTH = 0x7f */

    /* Issue soft reset command */
    msm_boot_uart_dm_reset(uart_dm_base);

    /* Enable/Disable Rx/Tx DM interfaces */
    /* Data Mover not currently utilized. */
    writel(0x0, MSM_BOOT_UART_DM_DMEN(uart_dm_base));

    /* Enable transmitter and receiver */
    writel(MSM_BOOT_UART_DM_CR_RX_ENABLE, MSM_BOOT_UART_DM_CR(uart_dm_base));
    writel(MSM_BOOT_UART_DM_CR_TX_ENABLE, MSM_BOOT_UART_DM_CR(uart_dm_base));

    /* Initialize Receive Path */
    msm_boot_uart_dm_init_rx_transfer(uart_dm_base);

    return MSM_BOOT_UART_DM_E_SUCCESS;
}

那麼從code中我們看到了它的設置，那麼為何它是這樣設置的？那麼就要看電路圖了！

vc/G5rnWtcTKx86qyrLDtKOsYXVkaW9kZWJ1Z7XEcGluysfI57rO0rK+zcrHZ3Bpbzg3ysfI57rOuaTX96Os1eK49s7Su+HOysHLRUW1xM2sysK686Os1NnX9r3itPChozwvcD4NCjxwPtbBtMujrGJvb3Rsb2FkZXKy47XEdWFydMrHyOe6zr2owaK1xKOs0tG+rdPQwcu63LrDtcS94srNo6y2+NTadGFyZ2V0X2luaXQoKbqvyv3U2cilyejWw9K7sd9ncGlvztK49sjLvvW1w8rHw7vT0LHY0qq1xKOhPC9wPg0KPGgyIGlkPQ=="後記">後記

system/core層logcat分析

在這裡我們清晰的看到了《Android系統源代碼情景分析》一書中提到的基礎數據結構體。具體路徑在/system/core/include/log/logger.h

/*
 * The userspace structure for version 1 of the logger_entry ABI.
 * This structure is returned to userspace by the kernel logger
 * driver unless an upgrade to a newer ABI version is requested.
 */
struct logger_entry {
    uint16_t    len;    /* length of the payload */
    uint16_t    __pad;  /* no matter what, we get 2 bytes of padding */
    int32_t     pid;    /* generating process's pid */
    int32_t     tid;    /* generating process's tid */
    int32_t     sec;    /* seconds since Epoch */
    int32_t     nsec;   /* nanoseconds */
    char        msg[0]; /* the entry's payload */
} __attribute__((__packed__));
/*
 * The maximum size of the log entry payload that can be
 * written to the logger. An attempt to write more than
 * this amount will result in a truncated log entry.
 */
#define LOGGER_ENTRY_MAX_PAYLOAD    4076

/*
 * The maximum size of a log entry which can be read from the
 * kernel logger driver. An attempt to read less than this amount
 * may result in read() returning EINVAL.
 */
#define LOGGER_ENTRY_MAX_LEN        (5*1024)

但是我越看越覺得不一樣，看來androidM的log機制已經發生了變化，於是我覺得有書不如無書，帶著這樣的想法我又細細讀了一遍。
決定再從init，kernel,framwork層分層去做解析，當然重點還是在kernel層。