6/18/2017

Kernel dmesg 및 debug 관련정보

1. Kernel Log 관련 정보 

Kernel의 printk의 Message이며 이 부분을 좀 다양하게 알아보자

1.1 dmesg  (/dev/kmsg , /proc/kmsg)

Linux에서 Kernel Message를 보는 방법은 dmesg이며 각각의 Log Level을 아래의 사이트는 각각의 나타내고 있다.

  • dmesg 기본사용법
  1. dmesg -c   :  dmesg  clear   dmeg도 내부에 buffer가 있기에 이를 전부 clear한다. 
  2. dmesg -n1 :  level 1 선택 
  3. dmesg      :   기본 설정값으로 하고 전부 출력.

  • raspberry pi test
dmesg로 처음 boot시 나왔던 kernel message 재확인하고 각부분 분석

$ dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.14.34-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1110 SMP Mon Apr 16 15:18:51 BST 2018
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x37800000
[    0.000000] On node 0 totalpages: 229376
[    0.000000] free_area_init_node: node 0, pgdat 80c84e40, node_mem_map b7016000
[    0.000000]   Normal zone: 2016 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 229376 pages, LIFO batch:31
[    0.000000] random: fast init done
[    0.000000] percpu: Embedded 17 pages/cpu @b6fbf000 s38720 r8192 d22720 u69632
[    0.000000] pcpu-alloc: s38720 r8192 d22720 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 227360
[    0.000000] Kernel command line: 8250.nr_uarts=0 bcm2708_fb.fbwidth=1920 bcm2708_fb.fbheight=1080 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=0c830106-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet splash plymouth.ignore-serial-consoles
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 887456K/917504K available (7168K kernel code, 575K rwdata, 2072K rodata, 1024K init, 706K bss, 21856K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xb8800000 - 0xff800000   (1136 MB)
                   lowmem  : 0x80000000 - 0xb8000000   ( 896 MB)
                   modules : 0x7f000000 - 0x80000000   (  16 MB)
                     .text : 0x80008000 - 0x80800000   (8160 kB)
                     .init : 0x80b00000 - 0x80c00000   (1024 kB)
                     .data : 0x80c00000 - 0x80c8fd4c   ( 576 kB)
                      .bss : 0x80c96f4c - 0x80d478b4   ( 707 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 25231 entries in 74 pages
[    0.000000] Hierarchical RCU implementation.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000019] Switching to timer-based delay loop, resolution 52ns
[    0.000267] Console: colour dummy device 80x30
[    0.000285] console [tty1] enabled
[    0.000311] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000326] pid_max: default: 32768 minimum: 301
[    0.000638] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000654] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001587] Disabling memory control group subsystem
[    0.001668] CPU: Testing write buffer coherency: ok
[    0.002063] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.002436] Setting up static identity map for 0x100000 - 0x10003c
[    0.002553] Hierarchical SRCU implementation.
[    0.003187] smp: Bringing up secondary CPUs ...
[    0.003869] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.004620] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.005351] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.005455] smp: Brought up 1 node, 4 CPUs
[    0.005465] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.005471] CPU: All CPU(s) started in HYP mode.
[    0.005475] CPU: Virtualization extensions available.
[    0.006318] devtmpfs: initialized
[    0.016951] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.017172] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.017190] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.017747] pinctrl core: initialized pinctrl subsystem
[    0.018489] NET: Registered protocol family 16
[    0.021208] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.026004] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.026011] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.026219] Serial: AMBA PL011 UART driver
[    0.027833] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.028291] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[    0.059373] bcm2835-dma 3f007000.dma: DMA legacy API manager at b8813000, dmachans=0x1
[    0.060896] SCSI subsystem initialized
[    0.061116] usbcore: registered new interface driver usbfs
[    0.061167] usbcore: registered new interface driver hub
[    0.061250] usbcore: registered new device driver usb
[    0.070084] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-04-16 18:21
[    0.071479] clocksource: Switched to clocksource arch_sys_counter
[    0.148866] VFS: Disk quotas dquot_6.6.0
[    0.148951] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.149138] FS-Cache: Loaded
[    0.149336] CacheFiles: Loaded
[    0.158147] NET: Registered protocol family 2
[    0.158869] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.158979] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.159165] TCP: Hash tables configured (established 8192 bind 8192)
[    0.159294] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.159337] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.159565] NET: Registered protocol family 1
[    0.160010] RPC: Registered named UNIX socket transport module.
[    0.160015] RPC: Registered udp transport module.
[    0.160021] RPC: Registered tcp transport module.
[    0.160026] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.161604] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.164342] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.172261] FS-Cache: Netfs 'nfs' registered for caching
[    0.172848] NFS: Registering the id_resolver key type
[    0.172878] Key type id_resolver registered
[    0.172884] Key type id_legacy registered
[    0.172899] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.174757] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    0.174878] io scheduler noop registered
[    0.174884] io scheduler deadline registered (default)
[    0.175161] io scheduler cfq registered
[    0.175168] io scheduler mq-deadline registered
[    0.175174] io scheduler kyber registered
[    0.177839] BCM2708FB: allocated DMA memory f7910000
[    0.177867] BCM2708FB: allocated DMA channel 0 @ b8813000
[    0.235976] Console: switching to colour frame buffer device 240x67
[    0.270983] bcm2835-rng 3f104000.rng: hwrng registered
[    0.271111] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.271631] vc-sm: Videocore shared memory driver
[    0.271898] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.281547] brd: module loaded
[    0.290519] loop: module loaded
[    0.290532] Loading iSCSI transport class v2.0-870.
[    0.291204] libphy: Fixed MDIO Bus: probed
[    0.291299] usbcore: registered new interface driver lan78xx
[    0.291355] usbcore: registered new interface driver smsc95xx
[    0.291373] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.519585] Core Release: 2.80a
[    0.519594] Setting default values for core params
[    0.519629] Finished setting default values for core params
[    0.719887] Using Buffer DMA mode
[    0.719893] Periodic Transfer Interrupt Enhancement - disabled
[    0.719898] Multiprocessor Interrupt Enhancement - disabled
[    0.719905] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.719914] Dedicated Tx FIFOs mode
[    0.720246] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xb7904000 dma = 0xf7904000 len=9024
[    0.720270] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.720277] dwc_otg: Microframe scheduler enabled
[    0.720329] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805e6a40
[    0.720340] WARN::hcd_init_fiq:460: FIQ ASM at 0x805e6da8 length 36
[    0.720352] WARN::hcd_init_fiq:486: MPHI regs_base at 0xb887e000
[    0.720408] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.720440] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.720470] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    0.720515] Init: Port Power? op_state=1
[    0.720521] Init: Power Port (0)
[    0.720734] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.720745] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.720754] usb usb1: Product: DWC OTG Controller
[    0.720762] usb usb1: Manufacturer: Linux 4.14.34-v7+ dwc_otg_hcd
[    0.720770] usb usb1: SerialNumber: 3f980000.usb
[    0.721409] hub 1-0:1.0: USB hub found
[    0.721451] hub 1-0:1.0: 1 port detected
[    0.722029] dwc_otg: FIQ enabled
[    0.722034] dwc_otg: NAK holdoff enabled
[    0.722039] dwc_otg: FIQ split-transaction FSM enabled
[    0.722048] Module dwc_common_port init
[    0.722296] usbcore: registered new interface driver usb-storage
[    0.722474] mousedev: PS/2 mouse device common for all mice
[    0.722550] IR NEC protocol handler initialized
[    0.722555] IR RC5(x/sz) protocol handler initialized
[    0.722561] IR RC6 protocol handler initialized
[    0.722567] IR JVC protocol handler initialized
[    0.722572] IR Sony protocol handler initialized
[    0.722577] IR SANYO protocol handler initialized
[    0.722582] IR Sharp protocol handler initialized
[    0.722587] IR MCE Keyboard/mouse protocol handler initialized
[    0.722594] IR XMP protocol handler initialized
[    0.723283] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    0.723544] bcm2835-cpufreq: min=600000 max=1200000
[    0.723896] sdhci: Secure Digital Host Controller Interface driver
[    0.723901] sdhci: Copyright(c) Pierre Ossman
[    0.724261] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[    0.724587] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    0.724679] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.726102] ledtrig-cpu: registered to indicate activity on CPUs
[    0.726283] hidraw: raw HID events driver (C) Jiri Kosina
[    0.726407] usbcore: registered new interface driver usbhid
[    0.726413] usbhid: USB HID core driver
[    0.727188] vchiq: vchiq_init_state: slot_zero = b7980000, is_master = 0
[    0.728641] [vc_sm_connected_init]: start
[    0.739161] [vc_sm_connected_init]: end - returning 0
[    0.739745] Initializing XFRM netlink socket
[    0.739769] NET: Registered protocol family 17
[    0.739872] Key type dns_resolver registered
[    0.740413] Registering SWP/SWPB emulation handler
[    0.741001] registered taskstats version 1
[    0.746970] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    0.747047] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[    0.748862] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    0.748871] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    0.802118] sdhost: log_buf @ b7907000 (f7907000)
[    0.837905] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    0.839475] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.841043] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.843833] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    0.881499] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    0.882567] of_cfs_init
[    0.882656] of_cfs_init: OK
[    0.883246] Waiting for root device PARTUUID=0c830106-02...
[    0.941724] Indeed it is in host mode hprt0 = 00021501
[    1.020851] mmc1: new high speed SDIO card at address 0001
[    1.042876] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.046001] mmc0: new high speed SDHC card at address aaaa
[    1.046477] mmcblk0: mmc0:aaaa SL16G 14.8 GiB
[    1.048863]  mmcblk0: p1 p2
[    1.066714] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
[    1.066722] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
[    1.075729] EXT4-fs (mmcblk0p2): recovery complete
[    1.079938] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.079992] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.087726] devtmpfs: mounted
[    1.090899] Freeing unused kernel memory: 1024K
[    1.151540] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.151666] Indeed it is in host mode hprt0 = 00001101
[    1.391795] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    1.391811] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.392527] hub 1-1:1.0: USB hub found
[    1.392610] hub 1-1:1.0: 5 ports detected
[    1.464634] systemd[1]: System time before build time, advancing clock.
[    1.590833] NET: Registered protocol family 10
[    1.592125] Segment Routing with IPv6
[    1.605413] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.628016] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    1.628567] systemd[1]: Detected architecture arm.
[    1.633541] systemd[1]: Set hostname to raspberrypi.
[    1.711668] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.851834] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    1.851882] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.854626] smsc95xx v1.0.6
[    1.955096] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:ef:b7:f8
[    2.073925] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    2.074345] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    2.074463] systemd[1]: Reached target Swap.
[    2.074757] systemd[1]: Listening on udev Kernel Socket.
[    2.075007] systemd[1]: Listening on Journal Socket (/dev/log).
[    2.095283] systemd[1]: Created slice System Slice.
[    2.098408] systemd[1]: Mounting Debug File System...
[    2.189973] i2c /dev entries driver
[    2.516225] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    2.582557] systemd-journald[92]: Received request to flush runtime journal from PID 1
[    3.150771] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    3.154509] bcm2835_alsa bcm2835_alsa: card created with 8 channels
[    3.371876] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[    3.387679] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
[    3.387960] usbcore: registered new interface driver brcmfmac
[    3.628839] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Oct 23 2017 03:55:53 version 7.45.98.38 (r674442 CY) FWID 01-e58d219f
[    3.629655] brcmfmac: brcmf_c_preinit_dcmds: CLM version = API: 12.2 Data: 7.11.15 Compiler: 1.24.2 ClmImport: 1.24.1 Creation: 2014-05-26 10:53:55 Inc Data: 9.10.39 Inc Compiler: 1.29.4 Inc ClmImport: 1.36.3 Creation: 2017-10-23 03:47:14 
[    4.529300] uart-pl011 3f201000.serial: no DMA platform data
[    5.390512] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    5.390583] brcmfmac: power management disabled
[    5.465582] random: crng init done
[    5.853760] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[    5.892712] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[    5.892864] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    6.420595] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[    9.093542] Bluetooth: Core ver 2.22
[    9.093638] NET: Registered protocol family 31
[    9.093646] Bluetooth: HCI device and connection manager initialized
[    9.093671] Bluetooth: HCI socket layer initialized
[    9.093684] Bluetooth: L2CAP socket layer initialized
[    9.093720] Bluetooth: SCO socket layer initialized
[    9.117196] Bluetooth: HCI UART driver ver 2.3
[    9.117215] Bluetooth: HCI UART protocol H4 registered
[    9.117221] Bluetooth: HCI UART protocol Three-wire (H5) registered
[    9.117443] Bluetooth: HCI UART protocol Broadcom registered
[    9.380735] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    9.380745] Bluetooth: BNEP filters: protocol multicast
[    9.380760] Bluetooth: BNEP socket layer initialized
[    9.444656] Bluetooth: RFCOMM TTY layer initialized
[    9.444687] Bluetooth: RFCOMM socket layer initialized
[    9.444708] Bluetooth: RFCOMM ver 1.11
[   10.518586] fuse init (API version 7.26)


  • printk의 시간표시 제어 
sys file을 이용하여 제어하는 것이지만, 제어가 되지 않아 추후 다시 테스트

$ cat /sys/module/printk/parameters/time
Y
$ sudo -s // root login 

$ echo 0 >/sys/module/printk/parameters/time

$ cat /sys/module/printk/parameters/time     // time parameter off 
N


  • Usermode에서 kernel message 전송 (/dev/kmsg)
$ echo "Hello Kernel-World" > /dev/kmsg  // Kernel Message 전송 

$ dmesg   // 확인결과 그대로 표시 , 흐음 추후 다시 테스트 
.....
[  209.198640] Hello Kernel-World

$ exit // root exit 


  • 실시간 Kernel Log 테스트 
$ sudo cat /proc/kmsg  &  // Kernel Debug 시작 
$ sudo -s
$ echo "Hello Kernel-World" > /dev/kmsg    // Kernel Debug Message 전송 
12 [ 4148.928694] Hello Kernel-World

$ dmesg  // 확인 
.....
[ 3980.591551] Hello Kernel-World


dmesg의 메시지가 많다보니, 보고 싶은 Message는 grep를 이용
  http://elinux.org/Debugging_by_printing
  http://man7.org/linux/man-pages/man1/dmesg.1.html

  http://m.blog.naver.com/koromoon/220581683064
  http://jybaek.tistory.com/130

1.2 syslog 의 Kernel Tag Message

아래의 message를 보기전에 항상 /etc/syslog.conf의 설정을 확인을 하자.

  • Log 정보분석 (syslog의 kernel tag)
$ cat /var/log/messages   // dmesg  보다 좀 더 자세한 정보 (memory 및 symbol)
Feb 17 15:59:58 raspberrypi kernel: [    4.786727] vc4-drm soc:gpu: bound 3f806000.vec (ops vc4_vec_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.786832] vc4-drm soc:gpu: bound 3f400000.hvs (ops vc4_hvs_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.787107] vc4-drm soc:gpu: bound 3f206000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.787330] vc4-drm soc:gpu: bound 3f207000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.787542] vc4-drm soc:gpu: bound 3f807000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.811151] vc4-drm soc:gpu: bound 3fc00000.v3d (ops vc4_v3d_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.818536] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
Feb 17 15:59:58 raspberrypi kernel: [    4.818554] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
Feb 17 15:59:58 raspberrypi kernel: [    4.818560] [drm] Driver supports precise vblank timestamp query.
Feb 17 15:59:58 raspberrypi kernel: [    4.891580] ------------[ cut here ]------------
Feb 17 15:59:58 raspberrypi kernel: [    4.891785] WARNING: CPU: 1 PID: 206 at drivers/gpu/drm/drm_atomic_helper.c:1240 drm_atomic_helper_wait_for_vblanks.part.0+0x268/0x26c [drm_kms_helper]
Feb 17 15:59:58 raspberrypi kernel: [    4.891796] [CRTC:67:crtc-2] vblank wait timed out
Feb 17 15:59:58 raspberrypi kernel: [    4.891802] Modules linked in: vc4(+) brcmfmac drm_kms_helper brcmutil drm snd_soc_core cfg80211 snd_compress snd_pcm_dmaengine snd_bcm2835(C) rfkill syscopyarea sysfillrect sysimgblt fb_sys_fops snd_pcm snd_timer snd i2c_bcm2835 uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6 cn
Feb 17 15:59:58 raspberrypi kernel: [    4.891944] CPU: 1 PID: 206 Comm: systemd-udevd Tainted: G         C      4.14.34-v7+ #1110
Feb 17 15:59:58 raspberrypi kernel: [    4.891953] Hardware name: BCM2835
Feb 17 15:59:58 raspberrypi kernel: [    4.891997] [8010ffd8] (unwind_backtrace) from [<8010c240>] (show_stack+0x20/0x24)
Feb 17 15:59:58 raspberrypi kernel: [    4.892025] [8010c240] (show_stack) from [<807840a4>] (dump_stack+0xd4/0x118)
Feb 17 15:59:58 raspberrypi kernel: [    4.892056] [807840a4] (dump_stack) from [<8011da54>] (__warn+0xf8/0x110)

.......


 $ cat /var/log/syslog  // Kernel (상위정보 포함) 과 init 관련 정보 
....
Feb 17 15:59:58 raspberrypi kernel: [    4.787107] vc4-drm soc:gpu: bound 3f206000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.787330] vc4-drm soc:gpu: bound 3f207000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.787542] vc4-drm soc:gpu: bound 3f807000.pixelvalve (ops vc4_crtc_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.811151] vc4-drm soc:gpu: bound 3fc00000.v3d (ops vc4_v3d_ops [vc4])
Feb 17 15:59:58 raspberrypi kernel: [    4.818536] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
Feb 17 15:59:58 raspberrypi kernel: [    4.818554] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
Feb 17 15:59:58 raspberrypi kernel: [    4.818560] [drm] Driver supports precise vblank timestamp query.
Feb 17 15:59:58 raspberrypi kernel: [    4.891580] ------------[ cut here ]------------
..........
Feb 17 15:59:59 raspberrypi dhcpcd-run-hooks[448]: wlan0: starting wpa_supplicant
Feb 17 15:59:59 raspberrypi systemd[1]: Received SIGRTMIN+21 from PID 210 (plymouthd).
Feb 17 15:59:59 raspberrypi systemd[1]: Started Hold until boot process finishes up.
Feb 17 15:59:59 raspberrypi systemd[1]: Started Terminate Plymouth Boot Screen.


2. Kernel의 proc를 이용한 Debug 


2.1  proc를 이용하여 symbol table 정보 찾기 

  • Kernel 의 __log_buf  직접접근
Memory가 Physical 0x800000000->0x0 변경.
상위 dmesg의 Virtual Kernel Memory Layout을 참조.

$ sudo grep __log_buf /proc/kallsyms  // Kernel Symbol 에서 __log_buf 검색
80c9aad0 b __log_buf                                         // Physical 과 Virtual Address Mapping (00000000->80000000) memory map 

$ sudo cat /proc/iomem      // SOC의 Periperal Memory (Memory Mapped IO)
00000000-3b3fffff : System RAM     // System RAM Address (Physcial Address)
  00008000-00afffff : Kernel code                // Kernel Code
  00c00000-00d478b3 : Kernel data         // Kernel Data (상위 symbol table 확인)
3f006000-3f006fff : dwc_otg
3f007000-3f007eff : /soc/dma@7e007000
3f00b840-3f00b84e : /soc/vchiq
3f00b880-3f00b8bf : /soc/mailbox@7e00b880
3f100000-3f100027 : /soc/watchdog@7e100000
3f101000-3f102fff : /soc/cprman@7e101000
3f200000-3f2000b3 : /soc/gpio@7e200000
3f201000-3f201fff : /soc/serial@7e201000
  3f201000-3f201fff : /soc/serial@7e201000
3f202000-3f2020ff : /soc/mmc@7e202000
3f206000-3f2060ff : /soc/pixelvalve@7e206000
3f207000-3f2070ff : /soc/pixelvalve@7e207000
3f212000-3f212007 : /soc/thermal@7e212000
3f215000-3f215007 : /soc/aux@0x7e215000
3f300000-3f3000ff : /soc/mmc@7e300000
3f400000-3f405fff : /soc/hvs@7e400000
3f805000-3f805fff : /soc/i2c@7e805000
3f806000-3f806fff : /soc/vec@7e806000
3f807000-3f8070ff : /soc/pixelvalve@7e807000
3f808000-3f8080ff : /soc/hdmi@7e902000
3f902000-3f9025ff : /soc/hdmi@7e902000
3f980000-3f98ffff : dwc_otg
3fc00000-3fc00fff : /soc/v3d@7ec00000


  • System RAM의 Symbol Table 정보확인

//////////////////////////////////////////////////////////////////////////////////
// 상위에서 알아본 __log_buf 의 symbol table의 주소를 상위 Kernel data 에 적용  
// 0x00c9aad0  = 0x00000000 (System RAM)  +  c9aad0 ( __log_buf)
// 상위와 같이 Physical Address 기반으로 변경 
//////////////////////////////////////////////////////////////////////////////////

$ sudo hexdump -s 0x00c9aad0  -n 80 -C /dev/mem   // -n 80  print line 

or

$ sudo hd -s 0x00c9aad0 -n 80000  /dev/mem  //  /dev/mem 접근가능하여 __log_buf 부분 확인 
00c9aad0  00 00 00 00 00 00 00 00  34 00 21 00 00 00 00 c6  |........4.!.....|
00c9aae0  42 6f 6f 74 69 6e 67 20  4c 69 6e 75 78 20 6f 6e  |Booting Linux on|
00c9aaf0  20 70 68 79 73 69 63 61  6c 20 43 50 55 20 30 78  | physical CPU 0x|
00c9ab00  30 00 00 00 00 00 00 00  00 00 00 00 a8 00 98 00  |0...............|
00c9ab10  00 00 00 a6 4c 69 6e 75  78 20 76 65 72 73 69 6f  |....Linux versio|
00c9ab20  6e 20 34 2e 31 34 2e 33  34 2d 76 37 2b 20 28 64  |n 4.14.34-v7+ (d|
00c9ab30  63 34 40 64 63 34 2d 58  50 53 31 33 2d 39 33 33  |c4@dc4-XPS13-933|
00c9ab40  33 29 20 28 67 63 63 20  76 65 72 73 69 6f 6e 20  |3) (gcc version |
00c9ab50  34 2e 39 2e 33 20 28 63  72 6f 73 73 74 6f 6f 6c  |4.9.3 (crosstool|
00c9ab60  2d 4e 47 20 63 72 6f 73  73 74 6f 6f 6c 2d 6e 67  |-NG crosstool-ng|
00c9ab70  2d 31 2e 32 32 2e 30 2d  38 38 2d 67 38 34 36 30  |-1.22.0-88-g8460|
00c9ab80  36 31 31 29 29 20 23 31  31 31 30 20 53 4d 50 20  |611)) #1110 SMP |
00c9ab90  4d 6f 6e 20 41 70 72 20  31 36 20 31 35 3a 31 38  |Mon Apr 16 15:18|

.......
00c9f9d0  02 00 00 00 2c 00 1c 00  00 00 00 c6 66 75 73 65  |....,.......fuse|
00c9f9e0  20 69 6e 69 74 20 28 41  50 49 20 76 65 72 73 69  | init (API versi|
00c9f9f0  6f 6e 20 37 2e 32 36 29  91 ec 35 b5 30 00 00 00  |on 7.26)..5.0...|
00c9fa00  24 00 12 00 00 00 01 82  48 65 6c 6c 6f 20 4b 65  |$.......Hello Ke|
00c9fa10  72 6e 65 6c 2d 57 6f 72  6c 64 00 00 00 00 00 00  |rnel-World......|
00c9fa20  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|

// 추후 uboot에서 load address도 확인 후 uImage or zImage 도 확인 (미확인)

$ cat /proc/kallsyms  // System.map 과 비교 
80008000 T stext
80008000 T _text
8000808c t __create_page_tables
80008138 t __turn_mmu_on_loc
80008144 t __fixup_smp
800081ac t __fixup_smp_on_up
800081d0 t __fixup_pv_table
80008224 t __vet_atags
..............

System.map (CONFIG_KALLSYMS 설정)
  https://en.wikipedia.org/wiki/System.map
  http://www.embedded.com/design/debug-and-optimization/4441375/Self-testing-in-embedded-systems--Hardware-failure

2.2 이외 proc의 다양한 Kernel 정보 

/proc/sys/kernel에서 기본적인 kernel 관련정보를 볼 수 있다.

$ ls /proc/sys/kernel/
auto_msgmni                        perf_event_max_stack
cad_pid                            perf_event_mlock_kb
cap_last_cap                       perf_event_paranoid
core_pattern                       pid_max
core_pipe_limit                    poweroff_cmd
core_uses_pid                      print-fatal-signals
ctrl-alt-del                       printk          //이전의 printk 설정 및 보기 
dmesg_restrict                     printk_delay
domainname                         printk_devkmsg
firmware_config                    printk_ratelimit
hostname                           printk_ratelimit_burst
hotplug                           pty
keys                               random
kptr_restrict                      randomize_va_space
max_lock_depth                     real-root-dev
modprobe                          sched_child_runs_first
modules_disabled                   sched_rr_timeslice_ms
msgmax                             sched_rt_period_us
msgmnb                             sched_rt_runtime_us
msgmni                             sem
ngroups_max                        shm_rmid_forced
osrelease                          shmall
ostype                             shmmax
overflowgid                        shmmni
overflowuid                        sysctl_writes_strict
panic                              sysrq
panic_on_oops                      tainted
panic_on_rcu_stall                 threads-max
panic_on_warn                      timer_migration
perf_cpu_time_max_percent          usermodehelper
perf_event_max_contexts_per_stack  version

$ cat /proc/sys/kernel/sched_rr_timeslice_ms
100


3. Kernel 의 debugfs 설정 및 profile 

Kernel Config에서 Kernel hacking Menu에서 다양한 기능을 제공
Kernel의 menuconfig 에서 다양한 설정들을 확인필요
  1. Trace 기능 
  2. KGDB
  3. Memory Debug 기능


3.1 debug File system (/sys/kernel/debug)

Kernel config에 따라 변경되기 때문에 Kernel 설정확인

/sys/kernel/debug 의 Filesystem을 이용하여 Kernel의 내용을 Debug 하는 방법을 소개


$ mount | grep debugfs       // /sys/kernel/debug mount 되어있는지 확인
$ mount -t debugfs none /sys/kernel/debug   // 필요할 경우 사용 , 요즘 기본으로 되어있음
$ sudo -s   // root login 
$ ls /sys/kernel/debug/
bcm2708_fb  bluetooth   dma_buf   frontswap  irq       mmc1 pwm      sched_features  vchiq
bcm2835_thermal  brcmfmac    extfrag   gpio     kprobes   pinctrl regmap      sleep_time      vc-mem
bdi   cleancache  f2fs   hid     memblock  pm_genpd regulator    tracing      vc-smem
block   clk      fault_around_bytes  ieee80211  mmc0      pm_qos sched_debug  usb

$ cat /sys/kernel/debug/bluetooth/rfcomm  // bluetooth 관련정보확인 
b8:27:eb:45:1d:52 00:00:00:00:00:00 4 13
b8:27:eb:45:1d:52 00:00:00:00:00:00 4 7
b8:27:eb:45:1d:52 00:00:00:00:00:00 4 12

$ cat /sys/kernel/debug/usb/devices  // USB Host에서 Device Descriptor 정보 lsusb로 확인가능 

T:  Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=480  MxCh= 1
B:  Alloc=  0/800 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 2.00 Cls=09(hub  ) Sub=00 Prot=01 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0002 Rev= 4.19
S:  Manufacturer=Linux 4.19.35-1.1.0+g0f9917c ehci_hcd
S:  Product=EHCI Host Controller
S:  SerialNumber=ci_hdrc.1
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   4 Ivl=256ms
............

$ cat /sys/kernel/debug/gpio     // 상위 본인이 확인하고자 하는 정보 확인 
$ cat /sys/kernel/debug/pinctrl  // Pinmux 정보
$ /sys/kernel/debug/tracing  //tracing 기능 

  https://www.kernel.org/doc/Documentation/filesystems/debugfs.txt
  https://events.linuxfoundation.org/sites/events/files/slides/kernel_profiling_debugging_tools_0.pdf

3.2 Kernel Profile (oprofile)

  • Kernel Config 설정변경 
  1. CONFIG_PROFILING=y  (General setup)
  2. CONFIG_OPROFILE=y

  https://cateee.net/lkddb/web-lkddb/OPROFILE.html


  • File system의 변경 및 설치 Package
  1. oprofile package 설치
  2. /var/lib/oprofile  directory 필요

Oprofile Download
  https://oprofile.sourceforge.io/download/
  https://oprofile.sourceforge.io/examples/
  http://oprofile.sourceforge.net/about/

Oprofile 관련내용
  http://homepages.cwi.nl/~aeb/linux/profile.html
  https://oprofile.sourceforge.io/doc/index.html
  http://egloos.zum.com/furmuwon/v/10709926

Yocto Profile 관련 Manual
  https://yoctoproject.org/docs/1.8/profile-manual/profile-manual.html
  https://developer.ridgerun.com/wiki/index.php?title=Preparing_Yocto_Development_Environment_for_Debugging
  https://wiki.yoctoproject.org/wiki/Tracing_and_Profiling

댓글 없음 :