레이블이 Debug-BootChart인 게시물을 표시합니다. 모든 게시물 표시
레이블이 Debug-BootChart인 게시물을 표시합니다. 모든 게시물 표시

4/10/2017

Boot Time 관련 정리

1. Boot Time 관련사항 

OS에서 Boot Time은 최적화를 위해서 중요하며, 보다 빠른 실행을 봐야할 부분이 아닐까 싶다. 이전부터 Linux 기반으로 Boot Time을 줄이기 위해서
기본적으로 Kernel 의 불필요한 기능제거 부터 시작하여 File System의 구성을 최적화하고 정리하고 필요한 부분을 Ramdisk도 이용하기도 했다.


Serial로 Booting 을 보면 시간이 다 기록이 되기때문에 이것으로도 도움이 되지만, Boot TIme을 줄이기 위해서는 본인이 원하는 Service(Program) 실행되어지는 순서변경과
Boot Time의 정확한 측정방법이 파악이 아닐 까 싶다.

  • BootTime 에 관련부분 설명 문서 
  https://bootlin.com/doc/training/boot-time/
  https://elixir.bootlin.com/linux/latest/ident/
  http://www.bootchart.org/samples.html
  https://www.raspberrypi.org/forums/viewtopic.php?t=76606


  • TI Fast Boot Example 
  http://www.makelinux.com/emb/fastboot/
  http://www.makelinux.com/emb/fastboot/omap
  http://www.makelinux.com/emb/fastboot/dm365
  http://e2e.ti.com/support/embedded/linux/f/354/t/51158
  http://www.makelinux.com/emb/fastboot/dm6467
  http://processors.wiki.ti.com/index.php/Sitara_Linux_Training:_Boot_Time_Reduction

  • General Boot Time  관련내용
  1. Kernel Speed up 하는 법 
  2. Boot up Time 측정하는 법 

  http://tree.celinuxforum.org/CelfPubWiki/KoreaTechJamboree3?action=AttachFile&do=get&target=The_Fast_Booting_of_Embedded_Linux.pdf


1.1 Snapshot Booting 

Memory의 정보를 Snapshot 형태로 보관해서 이 부분을 Booting 하는 방식이며, DMA까지 이용한다고 한다.

  • FA linux의 zeroboot 
  http://www.falinux.com/kr/desktop/solution/zeroboot
  http://forum.falinux.com/zbxe/index.php?document_srl=561345&mid=falinux
  http://djji.tistory.com/entry/ZEROBOOT%EC%A0%9C%EB%A1%9C%EB%B6%80%ED%8A%B8

  • Snapshot boot
  http://elinux.org/images/c/c3/Elc2011_kang.pdf
  http://elinux.org/images/3/37/Snapshot-boot-final.pdf


2. Boot Time 분석 

Boo Time에 관련된 기본정보들이 있음

  https://elinux.org/Boot_Time

2.1 Kernel Log 및 Kernel Serial 로 시간분석 

dmesg 및 kernel log로 이부분을 확인이 가능

  https://ahyuo79.blogspot.com/2016/02/kernel-message.html
  https://ahyuo79.blogspot.com/2014/09/kernel-debug.html

  https://elinux.org/Printk_Times

2.2 systemd-analyze 이용 

Linux file system init의 구조가 sysvinit 에서 systemd로 변경이 되어지고 있으며, 혹은 혼합하여 사용중이다. (현재 TI는 혼합해서 사용하고 있기에 이를 적용하기 무리가 있다)
systemd의 분석기능을 제공하고 있으며, dmesg로 boot time을 체크하는 것과는 별도로 진행을 해야 할 것 같다. .

  https://ahyuo79.blogspot.com/2017/04/systemd-analyze.html
  https://wiki.archlinux.org/index.php/Improving_performance/Boot_process

2.3 bootchart/bootchart2 이용

기본적으로 busybox에서 제공을 해주고 있으며, Kernel parameter에서 init=/sbin/bootchartd 를 설정을 해주어야 동작이 가능

  https://ahyuo79.blogspot.com/2017/03/bootchart.html

4/03/2017

dmesg 와 systemd-analyze 비교

systemd에서는 각각의 실행시간을 분석해주는 Tool이 존재하며 이를 이용하여 각각의 실행시간을 알수가 있지만, 정확한 사용방법을 알아야한다.

아래의 결과는 Raspberry Pi에서 동일하게 실행한 결과이지만, 아래와 같이 시간이 제각각이다.


  • dmseg와 비교 
$ 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.000310] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000324] pid_max: default: 32768 minimum: 301
[    0.000640] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000654] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001589] Disabling memory control group subsystem
[    0.001669] CPU: Testing write buffer coherency: ok
[    0.002060] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.002435] Setting up static identity map for 0x100000 - 0x10003c
[    0.002553] Hierarchical SRCU implementation.
[    0.003188] smp: Bringing up secondary CPUs ...
[    0.003869] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.004618] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.005346] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.005449] smp: Brought up 1 node, 4 CPUs
[    0.005460] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.005465] CPU: All CPU(s) started in HYP mode.
[    0.005469] CPU: Virtualization extensions available.
[    0.006311] devtmpfs: initialized
[    0.016951] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.017174] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.017192] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.017748] pinctrl core: initialized pinctrl subsystem
[    0.018490] NET: Registered protocol family 16
[    0.021211] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.026008] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.026015] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.026219] Serial: AMBA PL011 UART driver
[    0.027834] 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.059383] bcm2835-dma 3f007000.dma: DMA legacy API manager at b8813000, dmachans=0x1
[    0.060908] SCSI subsystem initialized
[    0.061128] usbcore: registered new interface driver usbfs
[    0.061179] usbcore: registered new interface driver hub
[    0.061261] usbcore: registered new device driver usb
[    0.070088] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-04-16 18:21
[    0.071505] clocksource: Switched to clocksource arch_sys_counter
[    0.148883] VFS: Disk quotas dquot_6.6.0
[    0.148967] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.149154] FS-Cache: Loaded
[    0.149351] CacheFiles: Loaded
[    0.158152] NET: Registered protocol family 2
[    0.158874] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.158984] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.159170] TCP: Hash tables configured (established 8192 bind 8192)
[    0.159299] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.159343] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.159571] NET: Registered protocol family 1
[    0.160016] RPC: Registered named UNIX socket transport module.
[    0.160022] RPC: Registered udp transport module.
[    0.160027] RPC: Registered tcp transport module.
[    0.160032] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.161625] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.164360] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.172272] FS-Cache: Netfs 'nfs' registered for caching
[    0.172862] NFS: Registering the id_resolver key type
[    0.172900] Key type id_resolver registered
[    0.172906] Key type id_legacy registered
[    0.172921] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.174757] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    0.174881] io scheduler noop registered
[    0.174887] io scheduler deadline registered (default)
[    0.175165] io scheduler cfq registered
[    0.175173] io scheduler mq-deadline registered
[    0.175179] io scheduler kyber registered
[    0.177875] BCM2708FB: allocated DMA memory f7910000
[    0.177903] BCM2708FB: allocated DMA channel 0 @ b8813000
[    0.235713] Console: switching to colour frame buffer device 240x67
[    0.270742] bcm2835-rng 3f104000.rng: hwrng registered
[    0.270873] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.271359] vc-sm: Videocore shared memory driver
[    0.271668] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.281295] brd: module loaded
[    0.290358] loop: module loaded
[    0.290371] Loading iSCSI transport class v2.0-870.
[    0.291045] libphy: Fixed MDIO Bus: probed
[    0.291140] usbcore: registered new interface driver lan78xx
[    0.291196] usbcore: registered new interface driver smsc95xx
[    0.291213] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.519375] Core Release: 2.80a
[    0.519387] Setting default values for core params
[    0.519418] Finished setting default values for core params
[    0.719681] Using Buffer DMA mode
[    0.719687] Periodic Transfer Interrupt Enhancement - disabled
[    0.719693] Multiprocessor Interrupt Enhancement - disabled
[    0.719699] OTG VER PARAM: 0, OTG VER FLAG: 0
[    0.719710] Dedicated Tx FIFOs mode
[    0.720068] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xb7904000 dma = 0xf7904000 len=9024
[    0.720095] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    0.720102] dwc_otg: Microframe scheduler enabled
[    0.720158] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805e6a40
[    0.720169] WARN::hcd_init_fiq:460: FIQ ASM at 0x805e6da8 length 36
[    0.720182] WARN::hcd_init_fiq:486: MPHI regs_base at 0xb887e000
[    0.720238] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.720273] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.720305] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    0.720350] Init: Port Power? op_state=1
[    0.720355] Init: Power Port (0)
[    0.720566] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.720577] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.720585] usb usb1: Product: DWC OTG Controller
[    0.720594] usb usb1: Manufacturer: Linux 4.14.34-v7+ dwc_otg_hcd
[    0.720602] usb usb1: SerialNumber: 3f980000.usb
[    0.721235] hub 1-0:1.0: USB hub found
[    0.721274] hub 1-0:1.0: 1 port detected
[    0.721851] dwc_otg: FIQ enabled
[    0.721857] dwc_otg: NAK holdoff enabled
[    0.721862] dwc_otg: FIQ split-transaction FSM enabled
[    0.721872] Module dwc_common_port init
[    0.722108] usbcore: registered new interface driver usb-storage
[    0.722280] mousedev: PS/2 mouse device common for all mice
[    0.722356] IR NEC protocol handler initialized
[    0.722361] IR RC5(x/sz) protocol handler initialized
[    0.722367] IR RC6 protocol handler initialized
[    0.722372] IR JVC protocol handler initialized
[    0.722377] IR Sony protocol handler initialized
[    0.722382] IR SANYO protocol handler initialized
[    0.722388] IR Sharp protocol handler initialized
[    0.722393] IR MCE Keyboard/mouse protocol handler initialized
[    0.722398] IR XMP protocol handler initialized
[    0.723081] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
[    0.723342] bcm2835-cpufreq: min=600000 max=1200000
[    0.723695] sdhci: Secure Digital Host Controller Interface driver
[    0.723700] sdhci: Copyright(c) Pierre Ossman
[    0.724059] mmc-bcm2835 3f300000.mmc: could not get clk, deferring probe
[    0.724384] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    0.724475] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.725899] ledtrig-cpu: registered to indicate activity on CPUs
[    0.726080] hidraw: raw HID events driver (C) Jiri Kosina
[    0.726204] usbcore: registered new interface driver usbhid
[    0.726210] usbhid: USB HID core driver
[    0.726986] vchiq: vchiq_init_state: slot_zero = b7980000, is_master = 0
[    0.728438] [vc_sm_connected_init]: start
[    0.738907] [vc_sm_connected_init]: end - returning 0
[    0.739490] Initializing XFRM netlink socket
[    0.739515] NET: Registered protocol family 17
[    0.739614] Key type dns_resolver registered
[    0.740155] Registering SWP/SWPB emulation handler
[    0.740743] registered taskstats version 1
[    0.746682] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    0.746760] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[    0.748563] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
[    0.748573] mmc-bcm2835 3f300000.mmc: DMA channel allocated
[    0.802145] sdhost: log_buf @ b7907000 (f7907000)
[    0.841999] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    0.843546] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.845094] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    0.847873] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    0.881525] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    0.882587] of_cfs_init
[    0.882674] of_cfs_init: OK
[    0.883263] Waiting for root device PARTUUID=0c830106-02...
[    0.931645] Indeed it is in host mode hprt0 = 00021501
[    1.025154] mmc1: new high speed SDIO card at address 0001
[    1.062700] mmc0: host does not support reading read-only switch, assuming write-enable
[    1.066145] mmc0: new high speed SDHC card at address aaaa
[    1.066597] mmcblk0: mmc0:aaaa SL16G 14.8 GiB
[    1.068991]  mmcblk0: p1 p2
[    1.082349] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    1.082407] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    1.090094] devtmpfs: mounted
[    1.093347] Freeing unused kernel memory: 1024K
[    1.141555] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.141709] Indeed it is in host mode hprt0 = 00001101
[    1.381850] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    1.381866] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.382646] hub 1-1:1.0: USB hub found
[    1.382738] hub 1-1:1.0: 5 ports detected
[    1.467302] systemd[1]: System time before build time, advancing clock.
[    1.593629] NET: Registered protocol family 10
[    1.594870] Segment Routing with IPv6
[    1.607961] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.630555] 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.631146] systemd[1]: Detected architecture arm.
[    1.636234] systemd[1]: Set hostname to .
[    1.701617] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.831917] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    1.831933] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.834693] smsc95xx v1.0.6
[    1.935161] 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.088664] systemd[1]: Listening on fsck to fsckd communication Socket.
[    2.089776] systemd[1]: Created slice User and Session Slice.
[    2.090066] systemd[1]: Listening on Journal Socket (/dev/log).
[    2.090367] systemd[1]: Listening on Journal Socket.
[    2.090623] systemd[1]: Listening on udev Kernel Socket.
[    2.090869] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    2.091802] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    2.213886] i2c /dev entries driver
[    2.550410] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    2.636913] systemd-journald[85]: Received request to flush runtime journal from PID 1
[    3.188170] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    3.193560] bcm2835_alsa bcm2835_alsa: card created with 8 channels
[    3.324525] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[    3.335237] brcmfmac: brcmf_fw_map_chip_to_name: using brcm/brcmfmac43430-sdio.bin for chip 0x00a9a6(43430) rev 0x000001
[    3.335531] usbcore: registered new interface driver brcmfmac
[    3.586694] 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.587608] 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.653711] uart-pl011 3f201000.serial: no DMA platform data
[    5.262444] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    5.262495] brcmfmac: power management disabled
[    5.553997] Process accounting resumed
[    5.788790] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[    5.827103] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[    5.827305] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    7.266908] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[    9.231593] Bluetooth: Core ver 2.22
[    9.231749] NET: Registered protocol family 31
[    9.231756] Bluetooth: HCI device and connection manager initialized
[    9.233499] Bluetooth: HCI socket layer initialized
[    9.233524] Bluetooth: L2CAP socket layer initialized
[    9.233588] Bluetooth: SCO socket layer initialized
[    9.263519] Bluetooth: HCI UART driver ver 2.3
[    9.263534] Bluetooth: HCI UART protocol H4 registered
[    9.263541] Bluetooth: HCI UART protocol Three-wire (H5) registered
[    9.263800] Bluetooth: HCI UART protocol Broadcom registered
[    9.463472] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[    9.463481] Bluetooth: BNEP filters: protocol multicast
[    9.463503] Bluetooth: BNEP socket layer initialized
[    9.519323] Bluetooth: RFCOMM TTY layer initialized
[    9.519370] Bluetooth: RFCOMM socket layer initialized
[    9.519398] Bluetooth: RFCOMM ver 1.11
[   10.458720] fuse init (API version 7.26)


  • 전체시간- dmesg 비교 
dmesg의 정보와 비교해보면 각각의 시간차이가 존재하며, 이부분은 어쩔수 없는 것 같다.
일단 비교를 해보자.

$ systemd-analyze 
Startup finished in 1.422s (kernel) + 8.050s (userspace) = 9.472s

상위에서 Kernel이라고 생각하는 부분이 systemd의 첫번째 실행시간 같으며, 그전의 시간을 Kernel이라고 생각하는 것 같다.

요즘 Filesystem의 구조를 보면 sysvInit 구성에서 systemd의 구성으로 변경이 되고 있지만,혼재되어 사용되어지기 때문에 이를 가지고 정확한  데이타로 보기는 힘들것 같다.



  • Service 실행시간 비교 
아래부분은 systemd의 시간비교이기 때문에, Kernel 제외를 해야겠지만, init부분도 포함되어지는 것 같다.

$ systemd-analyze blame   // 상위가 마지막으로 실행된 서비스 
          4.893s hciuart.service
          1.917s networking.service
          1.600s dphys-swapfile.service
          1.210s bootchart.service
          1.200s bootchart-done.service
          1.186s dev-mmcblk0p2.device
          1.149s acct.service
          1.139s raspi-config.service
           719ms lightdm.service
           704ms keyboard-setup.service
           603ms systemd-logind.service
           368ms polkit.service
           359ms ssh.service
           329ms avahi-daemon.service
           322ms systemd-timesyncd.service
           314ms systemd-fsck@dev-disk-by\x2dpartuuid-0c830106\x2d01.service
           304ms systemd-udev-trigger.service
           291ms udisks2.service
           270ms systemd-fsck-root.service
           265ms systemd-udevd.service
           229ms rsyslog.service
           219ms dhcpcd.service
           201ms systemd-journald.service
           169ms fake-hwclock.service
           167ms gldriver-test.service
           160ms wifi-country.service
           156ms systemd-tmpfiles-setup-dev.service
           148ms triggerhappy.service
           144ms systemd-tmpfiles-setup.service
           134ms user@1000.service
           132ms bluetooth.service
           114ms plymouth-start.service
           112ms systemd-remount-fs.service
           105ms alsa-restore.service
           103ms sys-kernel-debug.mount
            97ms run-rpc_pipefs.mount
            90ms systemd-journal-flush.service
            81ms dev-mqueue.mount
            78ms systemd-update-utmp.service
            74ms kmod-static-nodes.service
            71ms systemd-random-seed.service
            70ms systemd-modules-load.service
            67ms boot.mount
            57ms systemd-sysctl.service
            53ms plymouth-read-write.service
            49ms console-setup.service
            48ms plymouth-quit-wait.service
            43ms systemd-update-utmp-runlevel.service
            34ms rc-local.service
            34ms nfs-config.service
            33ms systemd-rfkill.service
            32ms plymouth-quit.service
            27ms systemd-user-sessions.service
            26ms sys-kernel-config.mount
            17ms sys-fs-fuse-connections.mount



  • Target 분석 

Unit 단위로 Tree형태로 @와  offset 시간을 제공을 해주고 잇다.

$  systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @7.995s
└─multi-user.target @7.994s
  └─bluealsa.service @7.994s
    └─bluetooth.service @7.858s +132ms
      └─hciuart.service @2.958s +4.893s
        └─basic.target @2.768s
          └─sockets.target @2.768s
            └─avahi-daemon.socket @2.768s
              └─sysinit.target @2.766s
                └─systemd-timesyncd.service @2.442s +322ms
                  └─systemd-tmpfiles-setup.service @2.283s +144ms
                    └─local-fs.target @2.275s
                      └─run-user-1000.mount @6.960s
                        └─local-fs-pre.target @1.468s
                          └─keyboard-setup.service @760ms +704ms
                            └─system.slice @688ms
                              └─-.slice @568ms



  • 전체시간을 그림표현 

$ systemd-analyze plot > plot.svg   // svg 그림파일로 변경 
$ eog plot.svg   // svg 파일 확인 or 브라우저 확인 

기본이 Kernel Boot 부터 본인의 boot mode의 target (e.g multi-user.target)까지 의 분석이며, 착각하지 말아야 할거이 부팅때마다 다를 수 있다는 것을 명심하자




좀더 자세한 분석 방법은 아래의 메뉴얼참조
  https://jlk.fjfi.cvut.cz/arch/manpages/man/systemd-analyze.1
  https://wiki.archlinux.org/index.php/Improving_performance/Boot_process
  http://man7.org/linux/man-pages/man1/systemd-analyze.1.html

3/26/2017

bootchart

1. bootchart의 기능 

systemd에서 제공되는 boot에 관련된 시간을 측정을 해주는 프로그램이며, 현재 bootchart2까지의 기능을 제공을 해주고 있다.
물론 Kernel에서 printk의 옵션을 넣어 Serial에 Log로 각각의 시간을 볼수가 있지만, 이것은 어디까지나 printk 기반으로 하기 때문에,
bootchart는 init script 이후분석이라고 봐야할 것이다.(물론 Kernel의 모듈도 포함)


Bootchart 사이트
  http://www.bootchart.org/index.html
  http://www.bootchart.org/samples.html
  http://www.bootchart.org/images/bootchart.svgz


kernel의 cmdline에 init 부분을 설정
  https://elinux.org/Bootchart


상위의 정보를 보면 BusyBox에  Bootchart는 포함이 되어있으며, 설정을 하면 bootchard가 사용가능하다.


1.1 Raspberry Pi에서 bootchart 실행  


$ ls /sbin/boot*  // bootchartd 설치 확인 busybox로 설치가능 

$ sudo apt-get install bootchart bootchart-view

$ ls /sbin/boot*  //bootchartd 설치 확인 
/sbin/bootchartd

$cat /proc/cmdline   // Kernel Command line 확인 
8250.nr_uarts=0 cma=256M 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

$ cat /boot/cmdline.txt  // init 부분 미설정 확인 
dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=0c830106-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait

$ sudo vi /boot/cmdline.txt  // Raspberry Pi cmdline 수정가능 
dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=0c830106-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait init=/sbin/bootchartd

$ sudo reboot

$ cat /proc/cmdline
8250.nr_uarts=0 cma=256M 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 init=/sbin/bootchartd

$ ls /var/log/bootchart.tgz  // /sbin/bootchartd 로 bootchart.tgz 생성확인  
/var/log/bootchart.tgz

$ bootchart  //png 파일 생성 
Parsing /var/log/bootchart.tgz
Wrote image: ./bootchart.png

$ scp ./bootchart.png jhlee@192.168.1.101:/home/jhlee/


막상 사용해보니, 나에게는 거의 도움이 되지 않는 것 같으며, 추후 사용할 일 있다면 그때 사용하자.

raspberry pi 3 bootcmd 수정
  https://www.raspberrypi.org/documentation/configuration/cmdline-txt.md

Raspberry Pi는 쉽게 cmdline을 filesystem에서 수정이 가능하지만, 다른 Board일 경우는 Busybox와 uboot에서 적용해야겠다.



1.2 bootchart2 사용법 

bootchart2를 사용하면, 쉽게 python으로 /var/log/bootchart.tgz 정보를 쉽게 볼 수 있다.

$ sudo apt-get install bootchart2

$ pybootchartgui -i 

systemctl 사용법
  https://ahyuo79.blogspot.com/2017/03/systemctl.html

Android 관련 Boot Time 소개 (bootchart 포함)
  http://www.slideshare.net/kanru/android-boot-time-optimization

전체 BootTime에 관련된 정보
  https://elinux.org/Boot_Time

나에게는 그다지 큰 도움이 되지 않는 것 같으며, 오히려, systemd 분석도구 가 더 좋은 것 같다.