Чтение логов ядра из SDRAM при его падении с последующей перезагрузкой

Так случилось, что собраное мною ядро для китайфона (MSM8228) при тестировании заставляло оного переходить в EDL (Emergency Download) режим и выяснить причину такого поведения было абсолютно невозможно без логов ядра. Поэтому поставил себе цель: прочитать эти самые логи для понимания причин падений.

Конечно на ум сразу приходят два варианта: заставить ядро выводить логи на экран или при падении скидывать логи на eMMC устройство. Но оба эти варианты сложны, да и не предоставляют возможности получения логов на ранних этапах инициализации ядра. Остается только логирование в область памяти, которая бы не изменилась при перезагрузках системы. Как оказалось такая область памяти называется persistent ram (pram) и инициализируется в самом начале работы ядра. В данном случае под инициализацией понимается просто напросто резервирование участка памяти для особых целей.

Участок persistent ram обычно используется для работы устройства ram_console, которое нужно для формирование файла "/proc/last_kmsg" (и не только). Т.е. это устройство при падении ядра занимается созданием копии логов в области persistent ram, а при загрузке ядра создает файл last_kmsg. Наличие такого файла позволяет узнать о причинах падения ядра. Но если падение возникает на этапе инициализации подсистем ядра, то этот механизм бесполезен.

Физич адрес и размер persistent ram можно узнать при просмотре логов стокового ядра.

В ядро, которое используется в моем китайфоне, производитель просто напросто поленился добавить поддержку persistent ram и ram_console. Поэтому сперва мне нужно было выяснить физический адрес и размер pram. Как оказалось это довольно просто, т.к. при поиске информации на глаза попался вот такой кодес:

void __init lge_add_persist_ram_devices(void)
{
  int ret;
  struct memtype_reserve *mt = &reserve_info->memtype_reserve_table[MEMTYPE_EBI1];
  lge_persist_ram.start = mt->start - LGE_PERSISTENT_RAM_SIZE;  // SZ_256K
  pr_info("PERSIST RAM CONSOLE START ADDR : 0x%x\n", lge_persist_ram.start);
  ret = persistent_ram_early_init(&lge_persist_ram);
  if (ret) pr_err("%s: failed to initialize persistent ram\n", __func__);
}

Если взглянуть на ядерные логи стоковой прошивки, то можно определить адрес EBI области памяти. В моем случае адрес начала EBI = 0x7f300000. Обычно под область pram выделяют не более 2МБ (0x200000 байт). Поэтому в качестве начала области pmem я выбрал адрес, 0x7f100000 (в моем китайфоне установлено 2ГБ SDRAM).

Далее нужно было провести эксперимент, который показывал бы наглядно, что в этой области памяти (0x7f100000 ... 0x7f2fffff) данные не затираются после перезагрузки. Для этого пришлось стоковый образ boot.img разобрать на составляющие части. Затем пришлось декодировать файл dtb.img в DTS-файл (в предыдущей статье я об этом уже писал).

В результате получил файлик phone.dts , который описывает "внутренее строение" девайса (Flattened Device Tree). Открыл этот файлик на редактирование и добавил 1 строчку в самое начало:

/dts-v1/;

/memreserve/ 0x7f200000 0x100000;

/ {
      #address-cells = <0x1>;
      #size-cells = <0x1>;
      model = "Qualcomm MSM 8226v2 QRD";
      compatible = "qcom,msm8226-qrd", "qcom,msm8226", "qcom,qrd";

Команда memreserve заставляет ядро на самом раннем этапе зарезервировать указанную область физической памяти (первый мегабайт по адресу 0x7f100000 оставил для иных целей).

Далее скомпилировал phone.dts в dtb.img и при помощи утилиты AndImgTool собрал новый образ boot.img , в котором QCDT-структура имеет информацию о persistent ram.

При помощи команды "fastboot flash boot boot.img" обновил в девайсе ядро. После загрузки андройда установил утилиту devmem2 и выполнил команды:

$ su
$ ./devmem2 0x7f200000 w 0x51525354

Затем перезагрузил девайс и снова выполнил такие же команды. В консольном выводе увидел, что по адресу 0x7f200000 находилось значение 0x51525354. Значит данную область памяти можно смело использовать в качестве хранилища информации между различными состояниями девайса.

Стоит отметить, что при возникновении критической ошибки в ядре моё устройство перезагружается в EDL режим. Выход из этого режима возможен только при использовании кнопки Power. Но мои эксперименты показали, что использование Power в большинстве случаев влияет на содержимое памяти. Т.е. очень часто за место числа 0x51525354 считывалось число 0x8A805354 (видоизменялись байтики по адресам кратным 2 и 3). Видимо на разных устройствах будет как то иначе, но данное обстоятельство нужно обязательно учитывать.

Учитывая сказанное выше, можно составить список требований, при которых возможно прочесть логи при падении ядра:
1) обеспечить в тестируемом ядре резервирование 1МБ физической памяти (pram) по адресу 0x7f200000;
2) обеспечить в тестируемом ядре копирование логов из внутреннего буфера в зарезервированную область pram;
3) при падении тестируемого ядра обеспечить возможность загрузки стокового ядра без использования кнопки Power;
4) обеспечить в стоковом ядре резервирование 1МБ физической памяти по адресу 0x7f200000;
5) при загрузке стокового ядра обеспечить возможность считывания данных из SDRAM-памяти в файл.

Требование #1 реализуется добавлением в файл "/arch/arm/boot/dts/msm8xxx.dts" строчки "/memreserve/ 0x7f200000 0x100000".

Требование #2 реализуется добавлением в файлы printk.c и main.c нового функционала.
Сначала откроем файл "/kernel/printk.c".
В список хидеров нужно добавить ещё парочку:

#include <linux/io.h>
#include <linux/vmalloc.h>

Нужно найти функцию emit_log_char и сделать следующие исправления (выделено цветом):

static int log_no_ring = 0;

static int __init log_no_ring_setup(char *str)
{
  get_option(&str, &log_no_ring);
  return 0;
}
early_param("log_no_ring", log_no_ring_setup);

static void emit_log_char_pmem(char c);

static void emit_log_char(char c)
{
  static int is_begin;
  int start_apanic_threads;

  start_apanic_threads = is_apanic_threads_dump();
  if (unlikely(start_apanic_threads) && !is_begin) {
    is_begin = 1;
    log_end = 0;
    logged_chars = 0;
  }

  if (log_no_ring && log_end - log_start >= log_buf_len) goto exit;

  emit_log_char_pmem(c);

  LOG_BUF(log_end) = c;
  log_end++;
  if (log_end - log_start > log_buf_len)
    log_start = log_end - log_buf_len;
  if (log_end - con_start > log_buf_len)
    con_start = log_end - log_buf_len;
  if (logged_chars < log_buf_len)
    logged_chars++;

exit:
  if (unlikely(start_apanic_threads &&
    ((log_end & (LOG_BUF_MASK + 1)) == __LOG_BUF_LEN))) {
    emergency_dump();
    is_begin = 0;
  }
}

Затем в самый конец файла "/kernel/printk.c" следует добавить:

#define PMEM_LOG_ADDR   (0x7f200000)
#define PMEM_LOG_SIZE   (0x100000)
#define PMEM_LOG_PAGES  (PMEM_LOG_SIZE / PAGE_SIZE)

static int      pmem_log = 0;
static void   * pmem_virt = NULL;
static uint32_t pmem_log_size = 0;
static int      pmem_log_beg = 0;

static int __init pmem_log_setup(char *str)
{
  get_option(&str, &pmem_log);
  return 0;
}
early_param("pmemlog", pmem_log_setup);

int pmem_log_init(void)
{
  uint32_t x;
  pgprot_t prot;
  struct page **pages;
  phys_addr_t addr;

  if (!pmem_log) retrun 0;
  if (pmem_virt) return 1;
  
  prot = pgprot_noncached(PAGE_KERNEL);
  pages = kmalloc(sizeof(struct page *) * PMEM_LOG_PAGES, GFP_KERNEL);
  if (!pages) return 0;
  for (x = 0; x < PMEM_LOG_PAGES; x++) {
    addr = (phys_addr_t)PMEM_LOG_ADDR + x * PAGE_SIZE;
    pages[x] = pfn_to_page(addr >> PAGE_SHIFT);
  } 
  pmem_virt = vmap(pages, PMEM_LOG_PAGES, VM_MAP, prot);
  kfree(pages);
  if (!pmem_virt) return 0;  
  
  for (x = 0; x < PMEM_LOG_SIZE - PAGE_SIZE - 16; x += 4) {
    __raw_writel_no_log(0, (uint32_t)pmem_virt + x);
  }
  
  return 1;
}

int pmem_log_start(void)
{
  uint32_t x;
  if (!pmem_log) retrun 0;
  if (!pmem_virt) return 0;
  pmem_log_beg = 1;
  if (logged_chars < PMEM_LOG_SIZE - 100) {
    for (x = 0; x < logged_chars; x++) {
      __raw_writeb_no_log(log_buf[x], (uint32_t)pmem_virt + x);
    }
    __raw_writeb_no_log('\n', (uint32_t)pmem_virt + logged_chars);
    pmem_log_size = logged_chars + 1;
  }
  return 1;
}

static void emit_log_char_pmem(char c)
{
  if (pmem_log_beg && pmem_virt && pmem_log_size < PMEM_LOG_SIZE-16) {
    __raw_writeb_no_log(c, (uint32_t)pmem_virt + pmem_log_size);
    pmem_log_size++;
  }
}

Функция pmem_log_init инициализирует pram память под копию ядерного лога.
Функция emit_log_char_pmem встраивается в функцию emit_log_char и занимается наполнением нового буфера по адресу 0x7f200000.

Новая опция "pmem_log=1" включает функционал копирования лога в новый буфер.
Новая опция "log_no_ring=1" заставляет ядро остановить логирование при достижении конца внутреннего буфера (это бывает очень полезно). Поэтому при использовании этой опции так же следует указать "log_buf_len=512K", что заставит ядро выделить под лог 512КБ памяти.

Теперь откроем файл "/include/linux/printk.h" и в самый конец добавим пару строчек:

int pmem_log_init(void);
int pmem_log_start(void);

#endif

Теперь откроем файл "/kernel/main.c". Находим функцию do_basic_setup и в самое начало этой функции вставляем вызовы новых функций:

static void __init do_basic_setup(void)
{
  pmem_log_init();
  pmem_log_start();  
  cpuset_init_smp();
  usermodehelper_init();
  shmem_init();
  driver_init();
  init_irq_proc();
  do_ctors();
  usermodehelper_enable();
  do_initcalls();
}

Вызов этих двух функций заставил ядро дублировать логи в нашу область pram.

Требование #3 реализуется внесением изменений в файл "/arch/arm/mach-msm/restart.c".
Сначала находим определение переменной "download_mode" и изменяем его значение на "0":

/* Download mode master kill-switch */
static int dload_set(const char *val, struct kernel_param *kp);
static int download_mode = 0;
module_param_call(download_mode, dload_set, param_get_int,
   &download_mode, 0644);

Затем находим функцию msm_restart_prepare и изменяем код:

#define SOFTWARE_RESET          0x73727374  
#define FASTBOOT_MODE           0x77665500    
#define ADB_REBOOT              0x77665501  
#define RECOVERY_MODE           0x77665502  
#define UARTLOG_MODE            0x77665503  
#define NORMAL_BOOT             0x77665504
#define APANIC_REBOOT           0x77665505

static int panic_restart = 1;   // default ADB_REBOOT

static int __init panic_restart_setup(char *str)
{
  get_option(&str, &panic_restart);
  return 0;
}
early_param("panic_restart", panic_restart_setup);

static void msm_restart_prepare(const char *cmd)
{
#ifdef CONFIG_MSM_DLOAD_MODE

  /* This looks like a normal reboot at this point. */
  set_dload_mode(0);

  /* Write download mode flags if we're panic'ing */
  set_dload_mode(in_panic);

  /* Write download mode flags if restart_mode says so */
  if (restart_mode == RESTART_DLOAD)
    set_dload_mode(1);

  /* Kill download mode if master-kill switch is set */
  if (!download_mode)
    set_dload_mode(0);
#endif

  pm8xxx_reset_pwr_off(1);

  /* Hard reset the PMIC unless memory contents must be maintained. */
  if (get_dload_mode() || (cmd != NULL && cmd[0] != '\0') || in_panic)
    qpnp_pon_system_pwr_off(PON_POWER_OFF_WARM_RESET);
  else
    qpnp_pon_system_pwr_off(PON_POWER_OFF_HARD_RESET);
    
  if (cmd != NULL) {
    if (!strncmp(cmd, "bootloader", 10)) {
      __raw_writel(0x77665500, restart_reason);
    } else if (!strncmp(cmd, "recovery", 8)) {
      __raw_writel(0x77665502, restart_reason);
    } else if (!strcmp(cmd, "rtc")) {
      __raw_writel(0x77665503, restart_reason);
    } else if (!strncmp(cmd, "oem-", 4)) {
      unsigned long code;
      code = simple_strtoul(cmd + 4, NULL, 16) & 0xff;
      __raw_writel(0x6f656d00 | code, restart_reason);
    } else if (!strncmp(cmd, "edl", 3)) {
      enable_emergency_dload_mode();
    } else {
      __raw_writel(FASTBOOT_MODE + panic_restart, restart_reason);
    }
  } else {
    __raw_writel(FASTBOOT_MODE + panic_restart, restart_reason);
  }

  flush_cache_all();
  outer_flush_all();
}

Новая опция "panic_restart=2" заставит ядро при рестарте системы всегда запускаться с recovery раздела (точнее даёт команду бутлоадеру на запуск recovery). Т.е. даже при возникновении критической ошибки (panic) будет осуществлён переход в recovery режим.

Требование #4 лучше выполнять над TeamWin recovery (TWRP). В результате получится удобное средство для снятия ядерных логов, т.к. TWRP предоставляет терминал и файловый менеджер. Так вот при помощи утилиты AndImgTool нужно образ TWRP разобрать на составляющие части. При помощи утилит dtc и dtbToolCM в файл dtb.img нужно добавить строчку "/memreserve/ 0x7f200000 0x100000". Но разобранный образ TWRP пока не собираем.

Требование #5 реализуется добавлением в TWRP утилиты viewmem (скачать viewmem). Добавлять файлик viewmem нужно в ramdisk в директорию sbin. Вот теперь можно при помощи AndImgTool собрать дополненный TWRP. При этом не забудьте в cpiostatfile.txt добавить информацию по новому файлику viewmem:

"twrp_/ramdisk/sbin/libdl.so",32768,1000,1000,750
"twrp_/ramdisk/sbin/mpstat",40960,1000,1000,777
"twrp_/ramdisk/sbin/toolbox",32768,1000,1000,750
"twrp_/ramdisk/sbin/viewmem",32768,1000,1000,777
"twrp_/ramdisk/sbin/libstdc++.so",32768,1000,1000,750

Сборка прошивки.
В файле BoardConfig.mk найдите параметр BOARD_KERNEL_CMDLINE и добавьте к списку параметров новые: "log_buf_len=512K log_no_ring=1 pmem_log=1 panic_restart=2". Теперь нужно собрать ядро (команда "mka bootimage") и положить в свою заранее собранную прошивку, которая вызывает сбой системы.

Тестирование прошивки.
Через fastboot прошиваем новый TWRP, через который заливаем в девайс свою прошивку. Запускаем прошивку. Если возникнет критическая ошибка (panic), то произойдет рестарт, при котором будет автоматически запущен TWRP. При входе в TWRP запускаем терминал и выполняем команды:

$ su
$ viewmem 0x7f200000 0x100000 >/data/kmsg.txt

Затем при помощи файлового менеджера копируем файл "/data/kmsg.txt" на sdcard. После этого можно заняться изучением логов и исправлением багов.


Все вышесказанное применимо для платформы Qualcomm MSM8xxx.