休眠唤醒(suspend/resume)时长问题分析思路

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 

  • 1
    点赞
  • 2
    收藏
    觉得还不错? 一键收藏
  • 打赏
    打赏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包

打赏作者

a2591748032-随心所记

你的鼓励将是我创作的最大动力

¥1 ¥2 ¥4 ¥6 ¥10 ¥20
扫码支付:¥1
获取中
扫码支付

您的余额不足,请更换扫码支付或充值

打赏作者

实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值