1.echo 1 > /sys/power/pm_print_times 打开suspend/resume耗时开关。
如下:可以看到系统休眠时各阶段驱动模块的耗时打印,可用来帮助分析排查休眠耗时长的问题。
[ 267.398855] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:02: mdio_bus_phy_suspend+0x0/0xac returned 0 after 0 usecs
[ 267.400193] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:01: calling mdio_bus_phy_suspend+0x0/0xac @ 2047, parent: stmmac-0
[ 267.401607] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:01: mdio_bus_phy_suspend+0x0/0xac returned 0 after 0 usecs
[ 267.402945] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:00: calling mdio_bus_phy_suspend+0x0/0xac @ 2047, parent: stmmac-0
[ 267.404358] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:00: mdio_bus_phy_suspend+0x0/0xac returned 0 after 0 usecs
[ 267.405696] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:07: calling mdio_bus_phy_suspend+0x0/0xac @ 2047, parent: stmmac-0
[ 267.407133] <1>.(1)[2047:kworker/u4:3]mdio_bus stmmac-0:07: mdio_bus_phy_suspend+0x0/0xac returned 0 after 0 usecs
[ 267.408558] <1>.(1)[2047:kworker/u4:3]Generic PHY mdio-bus:01: calling mdio_bus_phy_suspend+0x0/0xac @ 2047, parent: mdio-bus
[ 267.410093] <1>.(1)[2047:kworker/u4:3]Generic PHY mdio-bus:01: mdio_bus_phy_suspend+0x0/0xac returned 0 after 84 usecs
[ 267.411494] <1>.(1)[2047:kworker/u4:3]Generic PHY mdio-bus:03: calling mdio_bus_phy_suspend+0x0/0xac @ 2047, parent: mdio-bus
[ 267.413023] <1>.(1)[2047:kworker/u4:3]Generic PHY mdio-bus:03: mdio_bus_phy_suspend+0x0/0xac returned 0 after 77 usecs
[ 267.417426] <1>.(1)[2047:kworker/u4:3]platform Fixed MDIO bus.0: calling platform_pm_suspend+0x0/0x5c @ 2047, parent: platform
[ 267.418885] <1>.(1)[2047:kworker/u4:3]platform Fixed MDIO bus.0: platform_pm_suspend+0x0/0x5c returned 0 after 0 usecs
[ 267.643941] <0>.(0)[2047:kworker/u4:3]mtd mtd9ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.645235] <0>.(0)[2047:kworker/u4:3]mtd mtd9ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.646410] <0>.(0)[2047:kworker/u4:3]mtd mtd9: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.647703] <0>.(0)[2047:kworker/u4:3]mtd mtd9: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.648873] <0>.(0)[2047:kworker/u4:3]mtd mtd8ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.650167] <0>.(0)[2047:kworker/u4:3]mtd mtd8ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.651342] <0>.(0)[2047:kworker/u4:3]mtd mtd8: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.652613] <0>.(0)[2047:kworker/u4:3]mtd mtd8: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.653782] <0>.(0)[2047:kworker/u4:3]mtd mtd7ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.655076] <0>.(0)[2047:kworker/u4:3]mtd mtd7ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.656251] <0>.(0)[2047:kworker/u4:3]mtd mtd7: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.657546] <0>.(0)[2047:kworker/u4:3]mtd mtd7: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.658716] <0>.(0)[2047:kworker/u4:3]mtd mtd6ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.660009] <0>.(0)[2047:kworker/u4:3]mtd mtd6ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.661184] <0>.(0)[2047:kworker/u4:3]mtd mtd6: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.662455] <0>.(0)[2047:kworker/u4:3]mtd mtd6: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.663625] <0>.(0)[2047:kworker/u4:3]mtd mtd5ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.664917] <0>.(0)[2047:kworker/u4:3]mtd mtd5ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.666093] <0>.(0)[2047:kworker/u4:3]mtd mtd5: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.667385] <0>.(0)[2047:kworker/u4:3]mtd mtd5: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.668557] <0>.(0)[2047:kworker/u4:3]mtd mtd4ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.669850] <0>.(0)[2047:kworker/u4:3]mtd mtd4ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.671025] <0>.(0)[2047:kworker/u4:3]mtd mtd4: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.672296] <0>.(0)[2047:kworker/u4:3]mtd mtd4: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.673464] <0>.(0)[2047:kworker/u4:3]mtd mtd3ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.674756] <0>.(0)[2047:kworker/u4:3]mtd mtd3ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.675931] <0>.(0)[2047:kworker/u4:3]mtd mtd3: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.677223] <0>.(0)[2047:kworker/u4:3]mtd mtd3: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.678393] <0>.(0)[2047:kworker/u4:3]mtd mtd2ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.679785] <0>.(0)[2047:kworker/u4:3]mtd mtd2ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.680963] <0>.(0)[2047:kworker/u4:3]mtd mtd2: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.682235] <0>.(0)[2047:kworker/u4:3]mtd mtd2: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.683405] <0>.(0)[2047:kworker/u4:3]mtd mtd1ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.684698] <0>.(0)[2047:kworker/u4:3]mtd mtd1ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.685873] <0>.(0)[2047:kworker/u4:3]mtd mtd1: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.687168] <0>.(0)[2047:kworker/u4:3]mtd mtd1: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.688338] <0>.(0)[2047:kworker/u4:3]mtd mtd0ro: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.689632] <0>.(0)[2047:kworker/u4:3]mtd mtd0ro: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.690807] <0>.(0)[2047:kworker/u4:3]mtd mtd0: calling mtd_cls_suspend+0x0/0x40 @ 2047, parent: 11005000.nfi
[ 267.692078] <0>.(0)[2047:kworker/u4:3]mtd mtd0: mtd_cls_suspend+0x0/0x40 returned 0 after 0 usecs
[ 267.710452] <0>.(0)[2047:kworker/u4:3]regulator regulator.35: calling
[ 267.712033] <0>.(0)[2047:kworker/u4:3]regulator regulator.35: regulator_suspend+0x0/0x74 returned 0 after 88 usecs
[ 267.713373] <0>.(0)[2047:kworker/u4:3]regulator regulator.34: calling
唤醒resume耗时长debug问题分析方法,如下,可以看到系统唤醒时各驱动子模块唤醒所耗时长:
[ 268.912918] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c40000.i2c0: calling mt_i2c_resume_noirq+0x0/0x7c @ 2047, parent: platform
[ 268.914323] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c40000.i2c0: mt_i2c_resume_noirq+0x0/0x7c returned 0 after 0 usecs
[ 268.915694] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c41000.i2c1: calling mt_i2c_resume_noirq+0x0/0x7c @ 2047, parent: platform
[ 268.917099] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c41000.i2c1: mt_i2c_resume_noirq+0x0/0x7c returned 0 after 0 usecs
[ 268.918418] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c42000.i2c2: calling mt_i2c_resume_noirq+0x0/0x7c @ 2047, parent: platform
[ 268.919821] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c42000.i2c2: mt_i2c_resume_noirq+0x0/0x7c returned 0 after 0 usecs
[ 268.921140] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c43000.i2c3: calling mt_i2c_resume_noirq+0x0/0x7c @ 2047, parent: platform
[ 268.922543] <0>.(0)[2047:kworker/u4:3]mt-i2c 11c43000.i2c3: mt_i2c_resume_noirq+0x0/0x7c returned 0 after 0 usecs
[ 268.923889] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_0_phy: calling genpd_resume_noirq+0x0/0xc0 @ 2047, parent: platform
[ 268.925443] <0>.(0)[2047:kworker/u4:3]sgmii resume_noirq done
[ 268.926192] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_0_phy: genpd_resume_noirq+0x0/0xc0 returned 0 after 732 usecs
[ 268.927620] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_0_top: calling genpd_resume_noirq+0x0/0xc0 @ 2047, parent: platform
[ 268.929110] <0>.(0)[2047:kworker/u4:3]sgmii resume_noirq done
[ 268.929855] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_0_top: genpd_resume_noirq+0x0/0xc0 returned 0 after 728 usecs
[ 268.931283] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_1_phy: calling genpd_resume_noirq+0x0/0xc0 @ 2047, parent: platform
[ 268.932772] <0>.(0)[2047:kworker/u4:3]sgmii resume_noirq done
[ 268.933518] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_1_phy: genpd_resume_noirq+0x0/0xc0 returned 0 after 728 usecs
[ 268.935012] <0>.(0)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_1_top: calling genpd_resume_noirq+0x0/0xc0 @ 2047, parent: platform
[ 268.936541] <1>.(1)[2047:kworker/u4:3]sgmii resume_noirq done
[ 268.937298] <1>.(1)[2047:kworker/u4:3]sgmii_bring_up pd-sgmii_1_top: genpd_resume_noirq+0x0/0xc0 returned 0 after 739 usecs
[ 268.938750] <1>.(1)[2047:kworker/u4:3]sgmii-up snps-pdsgmii_0_phy: calling genpd_resume_noirq+0x0/0xc0 @ 2047, parent: platform
[ 268.940221] <1>.(1)[2047:kworker/u4:3]sgmii resume_noirq done
[ 268.940967] <1>.(1)[2047:kworker/u4:3]sgmii-up snps-pdsgmii_0_phy: genpd_resume_noirq+0x0/0xc0 returned 0 after 729 usecs
[ 268.942373] <1>.(1)[2047:kworker/u4:3]sgmii-up snps-pdsgmii_0_top: calling genpd_resume_noirq+0x0/0xc0 @ 2047, parent: platform
[ 268.943842] <1>.(1)[2047:kworker/u4:3]sgmii resume_noirq done
[ 268.944587] <1>.(1)[2047:kworker/u4:3]sgmii-up snps-pdsgmii_0_top: genpd_resume_noirq+0x0/0xc0 returned 0 after 727 usecs
2.echo 1 > /sys/module/kernel/parameters/initcall_debug 休眠唤醒子模块debug开关
如下:可以看到系统休眠时的一些打印信息,方便分析各模块是否进入suspend流程
[ 268.866345] <0>-(0)[2047:kworker/u4:3]PM: Calling dpmaif_syssuspend+0x0/0x1c
[ 268.869414] <0>-(0)[2047:kworker/u4:3]PM: Calling ccci_modem_syssuspend+0x0/0x44
[ 268.870363] <0>-(0)[2047:kworker/u4:3]PM: Calling sched_clock_suspend+0x0/0x3c
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling timekeeping_suspend+0x0/0x210
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling fw_suspend+0x0/0x24
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling scp_ipi_syscore_dbg_suspend+0x0/0x1c
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling clkchk_syscore_suspend+0x0/0x2c
[ 268.871285] <0>-(0)[2047:kworker/u4:3][clkchk] Enter CLOCK suspend Call Back !!
同理唤醒时也可以看到一些多的debug打印信息:
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling clkdbg_syscore_resume+0x0/0x18
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling clkchk_syscore_resume+0x0/0x24
[ 268.871285] <0>-(0)[2047:kworker/u4:3][clkchk] Enter CLOCK resume Call Back !!
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling scp_ipi_syscore_dbg_resume+0x0/0x18
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling irq_pm_syscore_resume+0x0/0x20
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling timekeeping_resume+0x0/0x14c
[ 268.871285] <0>-(0)[2047:kworker/u4:3]PM: Calling sched_clock_resume+0x0/0x54