I have developed a small application running with Amlogic’s Buildroot on VIM. From time to time, an unexpected CPU suspend is issued:
[19201.564788@0] codec:audio pts started::::::: 1
bl30 get wakeup sources!
process command 00000006
bl30 enter suspend!
cpu clk suspend rate 1000000000
suspend_counter: 1
Enter ddr suspend
first time suspend
ddr suspend time: 1887us
store restore gp0 pll
process command 00000001
CEC cfg:0x0000
set vddee to 0x035cmv
08915d0000000000exit_reason:0x06
set vddee to 0x03e8mv
set vcck to 0x0460mv
store restore gp0 pll
gp0 pll can't lock
read gp0_ctrl 40000000
read gp0_ctrl2 0
read gp0_ctrl3 0
read gp0_ctrl4 0
Enter ddr resume
ddr resume time: 372us
cfg15 3b01000
cfg15 63b01000
cpu c[20192.850197@0] [aml_is_card_insert] card OUT
[20192.850334@0] usb 1-1: USB disconnect, device number 2
#
#
#
#
# lk resume rate 1000000000
[20192.950090@0] aml_spdif_dai: aiu 958 playback disable
If the power button of the VIM is used to wake up the board (from exit_reason:0x06
in the log above), then the system does not work properly because Linux has not gone through a proper suspend/resume sequence.
This could be caused by a spurious call to cpu_suspend in the kernel, or by something in bl30.bin, but there are no source files for it. Any idea?
For reference, a suspend generated on purpose with the power button looks like the log below, and everything works fine after resumption:
[ 296.116223@0] codec:audio pts started::::::: 1
# [ 322.389481@0] input input1: key 116 down
[ 322.569436@0] input input1: key 116 up
[ 322.570001@0] request_suspend_state: sleep (3->3) at 322540682652 (2015-01-01 00:43:51.845296026 UTC)
[ 322.576720@0] request_suspend_state,164,old_sleep=0,new_state=3
[ 322.582694@0] early_suspend: call handlers
[ 322.609401@0] avmute set to 2
[ 322.711654@0] hdmitx: system: HDMITX: early suspend
[ 322.711702@0] hdmitx: system: unmux DDC for gpio read edid
[ 322.716364@0]
[ 322.716364@0] vdac_enable: on:0,module_sel:8
[ 323.729366@0] stop_drawing_early_suspend: timeout waiting for userspace to stop drawing
[ 323.731992@0] fb: osd_suspended
[ 323.734884@0] gxbb_pm: meson_system_early_suspend
[ 323.740606@0] early_suspend: sync
[ 323.751453@0] PM: suspend entry 2015-01-01 00:43:53.026747485 UTC
[ 323.751974@0] PM: Syncing filesystems ... done.
[ 323.830231@0] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 323.831717@0] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 323.839821@0] force to skip cfg80211_leave_all due to wifi suspend/resume issue
[ 323.846514@0] bcmsdh_sdmmc_suspend Enter func->num=2
[ 323.851434@0] bcmsdh_sdmmc_suspend Exit
[ 323.855184@0] bcmsdh_sdmmc_suspend Enter func->num=1
[ 323.891152@0] aml_spdif_dai: aiu 958 playback disable
[ 323.891199@0] aml_snd_card: enter aml_suspend_pre
[ 323.896333@0] aml_T9015_audio_suspend!
[ 323.898970@0] aml_snd_card: enter aml_suspend_post
[ 323.903925@0] amvecm: suspend module
[ 323.907260@0] vdin_drv_suspend ok.
[ 323.910622@0] vdin_drv_suspend ok.
[ 323.914238@0] sysled: module suspend ok
[ 323.917809@0] meson-remote c8100580.rc: remote suspend
[ 323.923008@0] PM: suspend of devices complete after 83.261 msecs
[ 323.928799@0] gxbb_pm: enter meson_pm_prepare!
[ 323.933659@0] di: di_suspend
[ 323.936124@0] PM: late suspend of devices complete after 2.928 msecs
[ 323.943069@0] PM: noirq suspend of devices complete after 0.702 msecs
[ 323.948738@0] Disabling non-boot CPUs ...
[ 323.952779@0] gxbb_pm: enter meson_pm_suspend!
[ 323.952779@0] gxbb_pm: late_suspend: call handlers
[ 323.952779@0] gxbb_pm: late_suspend: sync
bl30 get wakeup sources!
process command 00000006
bl30 enter suspend!
cpu clk suspend rate 1000000000
suspend_counter: 1
Enter ddr suspend
first time suspend
ddr suspend time: 1886us
store restore gp0 pll
process command 00000001
CEC cfg:0x0000
set vddee to 0x035cmv
08915d0000000000exit_reason:0x06
set vddee to 0x03e8mv
set vcck to 0x0460mv
store restore gp0 pll
gp0 pll can't lock
read gp0_ctrl 40000000
read gp0_ctrl2 0
read gp0_ctrl3 0
read gp0_ctrl4 0
Enter ddr resume
ddr resume time: 372us
cfg15 3b00000
cfg15 63b00000
[ 323.952779@0] gxbb_pm: late_resume: ccall handlers
[ 323.952779@0] gxbb_pm: late_resume: done
[ 323.952779@0] gxbb_pm: ... wake up
[ 323.953317@0] PM: noirq resume of devices complete after 0.464 msecs
[ 323.959189@0] [aml_is_card_insert] card OUT
[ 323.963325@0] di: resume module
[ 323.966596@0] PM: early resume of devices complete after 3.327 msecs
[ 323.972551@0] gxbb_pm: enter meson_pm_finish!
[ 323.978736@0] meson-remote c8100580.rc: remote resume
[ 323.981909@0] input input1: key 116 down
[ 323.985853@0] meson-remote c8100580.rc: default protocol = 0x1 and id = 0
[ 323.992449@0] meson-remote c8100580.rc: reg=0x0, val=0x1f40190
[ 323.998227@0] meson-remote c8100580.rc: reg=0x4, val=0x12c00c8
[ 324.004006@0] meson-remote c8100580.rc: reg=0x8, val=0x960050
[ 324.009698@0] meson-remote c8100580.rc: reg=0xc, val=0x480028
[ 324.015391@0] meson-remote c8100580.rc: reg=0x10, val=0x70fa0013
[ 324.021342@0] meson-remote c8100580.rc: reg=0x18, val=0x8616800
[ 324.027207@0] meson-remote c8100580.rc: reg=0x1c, val=0x9f00
[ 324.032813@0] meson-remote c8100580.rc: reg=0x20, val=0x0
[ 324.038161@0] meson-remote c8100580.rc: reg=0x24, val=0x0
[ 324.043508@0] meson-remote c8100580.rc: reg=0x28, val=0x0
[ 324.049731@0] sysled: module resume ok
[ 324.052642@0] vdin_drv_resume ok.
[ 324.055847@0] vdin_drv_resume ok.
[ 324.059152@0] amvecm: resume module
[ 324.062637@0] amhdmitx: resume module 3687
[ 324.066673@0] meson_uart c81004e0.serial: ttyS4 use xtal(8M) 24000000 change 19200 to 19200
[ 324.074996@0] aml_snd_card: enter aml_resume_pre
[ 324.079497@0] aml_T9015_audio_resume!
[ 324.084117@0] gpio keypad wakeup
pu clk resume rate 1000000000
[ 324.129294@0] input input1: key 116 up
[ 324.160364@0] libphy: set driving length c
[ 324.160465@0] libphy: set PLL minimum jitter
[ 324.288078@0] emmc: trying cali 0-th time(s)
[ 324.289820@0] aml_snd_card: enter aml_resume_post
[ 324.296584@0] emmc: delay[0]= 800 padding= 1, bidx=0
[ 324.296609@0] emmc: delay[1]= 1400 padding= 3, bidx=1
[ 324.301395@0] emmc: delay[2]= 800 padding= 1, bidx=0
[ 324.306396@0] emmc: delay[3]= 1200 padding= 4, bidx=1
[ 324.311418@0] emmc: delay[4]= 1200 padding= 4, bidx=1
[ 324.316400@0] emmc: delay[5]= 800 padding= 1, bidx=0
[ 324.321398@0] emmc: delay[6]= 1200 padding= 4, bidx=1
[ 324.326404@0] emmc: delay[7]= 1000 padding= 5, bidx=1
[ 324.331403@0] emmc: calibration result @ 0: max(1400), min(800)
[ 324.337272@0] emmc: line_delay =0x21311303, max_cal_result =1400
[ 324.343484@0] emmc: base_index_max 1, base_index_min 0
[ 324.348322@0] emmc: clk 100000000 SDR mode tuning start
[ 324.353899@0] emmc: rx_tuning_result[0] = 10
[ 324.358067@0] emmc: rx_tuning_result[1] = 10
[ 324.362315@0] emmc: rx_tuning_result[2] = 10
[ 324.366518@0] emmc: rx_tuning_result[3] = 10
[ 324.370781@0] emmc: rx_tuning_result[4] = 10
[ 324.374678@0] [mmc_cmd_LBA_show] emmc: cmd 21, arg 0x13800, operation is in [reserved] disk!
[ 324.383370@0] emmc: rx_tuning_result[6] = 10
[ 324.387565@0] emmc: rx_tuning_result[7] = 10
[ 324.391795@0] emmc: rx_tuning_result[8] = 10
[ 324.396013@0] emmc: rx_tuning_result[9] = 10
[ 324.399914@0] emmc: best_win_start =6, best_win_size =9
[ 324.405053@0] emmc: sd_emmc_regs->gclock=0x100024a,sd_emmc_regs->gadjust=0x2000
[ 324.412318@0] emmc: gclock =0x100024a, gdelay=0x21311303, gadjust=0x2000
[ 324.419131@0] emmc: support driver strength type 1
[ 324.423797@0] emmc: try set sd/emmc to DDR mode
[ 324.428182@0] emmc: try set sd/emmc to DDR mode
[ 324.433232@0] bcmsdh_sdmmc_resume Enter func->num=1
[ 324.437509@0] bcmsdh_sdmmc_resume Enter func->num=2
[ 324.442330@0] bcmsdh_sdmmc_resume Exit
[ 324.753179@0] usb 1-1: reset high-speed USB device number 2 using xhci-hcd
[ 324.754436@0] xhci-hcd xhci-hcd.0.auto: Setup ERROR: setup context command for slot 1.
[ 324.879324@0] usb 1-1: reset high-speed USB device number 2 using xhci-hcd
[ 324.880571@0] xhci-hcd xhci-hcd.0.auto: Setup ERROR: setup context command for slot 1.
[ 324.999323@0] usb 1-1: reset high-speed USB device number 2 using xhci-hcd
[ 325.019443@0] xhci-hcd xhci-hcd.0.auto: xHCI xhci_drop_endpoint called with disabled ep ffffffc058519640
[ 325.149649@0] PM: resume of devices complete after 1172.782 msecs
[ 325.152154@0] Restarting tasks ...
[ 325.154961@0] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, same source mode(0)
[ 325.163048@0] request_suspend_state: wakeup (3->0) at 325133780903 (2015-01-01 00:59:07.366086003 UTC)
[ 325.170807@0] request_suspend_state,164,old_sleep=1,new_state=0
[ 325.176667@0] wakeup wake lock: main
[ 325.183106@0] done.
[ 325.183362@0] fb: osd_open index=0,open_count=3
[ 325.186883@0] PM: suspend exit 2015-01-01 00:59:07.389928712 UTC
[ 325.193264@0] aml_spdif_dai: set normal 512 fs /4 fs
Here, the Linux suspend/resume operations are properly executed, and the values of cfg15 are different from those of the spurious case, but I don’t know what they mean.