On 03/12/2018 17:53, Marc Gonzalez wrote: > [ 0.970565] qcom-qmp-phy 1da7000.phy: Linked as a consumer to regulator.15 > [ 0.970676] qcom-qmp-phy 1da7000.phy: Linked as a consumer to regulator.16 > [ 0.971349] qcom-qmp-phy 1da7000.phy: Registered Qcom-QMP phy > [ 2.293324] ufshcd-qcom 1da4000.ufshc: ufshcd_populate_vreg: Unable to find vdd-hba-supply regulator, assuming enabled > [ 2.355902] ufshcd-qcom 1da4000.ufshc: Linked as a consumer to regulator.34 > [ 2.359197] ufshcd-qcom 1da4000.ufshc: Linked as a consumer to regulator.40 > [ 2.365857] ufshcd-qcom 1da4000.ufshc: Linked as a consumer to regulator.5 > [ 2.400665] scsi host0: ufshcd > [ 2.435181] ufshcd-qcom 1da4000.ufshc: ufshcd_print_pwr_info:[RX, TX]: gear=[1, 1], lane[1, 1], pwr[SLOWAUTO_MODE, SLOWAUTO_MODE], rate = 0 > [ 3.968211] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag: Sending flag query for idn 1 failed, err = -11 > [ 5.472133] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag: Sending flag query for idn 1 failed, err = -11 > [ 6.976114] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag: Sending flag query for idn 1 failed, err = -11 > [ 6.976387] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag_retry: query attribute, opcode 6, idn 1, failed with error -11 after 3 retires > [ 6.984999] ufshcd-qcom 1da4000.ufshc: ufshcd_complete_dev_init setting fDeviceInit flag failed with error -11 The PHY and MAC init *seem* successful, but obviously something goes wrong, since the query times out after 1500 ms, waiting for the completion in ufshcd_wait_for_dev_cmd() #define QUERY_REQ_TIMEOUT 1500 /* 1.5 seconds */ err is set to -ETIMEDOUT (i.e. -110) then the command is cleared for an ulterior retry, and err is set to -EAGAIN (i.e. -11) The question is: why does the command time out? Enabling DEBUG... [ 2.046246] ufshcd-qcom 1da4000.ufshc: ufshcd_populate_vreg: Unable to find vdd-hba-supply regulator, assuming enabled [ 2.046675] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: core_clk, rate: 198400000 [ 2.056101] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: bus_aggr_clk, rate: 198400000 [ 2.064333] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: iface_clk, rate: 0 [ 2.072820] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: core_clk_unipro, rate: 0 [ 2.080304] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: core_clk_ice, rate: 0 [ 2.088547] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: ref_clk, rate: 0 [ 2.096269] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: tx_lane0_sync_clk, rate: 0 [ 2.103743] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: rx_lane0_sync_clk, rate: 0 [ 2.111812] ufshcd-qcom 1da4000.ufshc: ufshcd_init_clocks: clk: rx_lane1_sync_clk, rate: 0 [ 2.120178] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: core_clk enabled [ 2.128292] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: bus_aggr_clk enabled [ 2.135848] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: iface_clk enabled [ 2.143833] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: core_clk_unipro enabled [ 2.151831] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: core_clk_ice enabled [ 2.160312] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: ref_clk enabled [ 2.167789] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: tx_lane0_sync_clk enabled [ 2.175444] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: rx_lane0_sync_clk enabled [ 2.184043] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: rx_lane1_sync_clk enabled [ 2.201054] ufshcd-qcom 1da4000.ufshc: Linked as a consumer to regulator.34 [ 2.204116] ufshcd-qcom 1da4000.ufshc: Linked as a consumer to regulator.40 [ 2.210800] ufshcd-qcom 1da4000.ufshc: Linked as a consumer to regulator.5 The zero clock rates look suspicious, don't they? [ 2.255243] ufshcd-qcom 1da4000.ufshc: ufshcd_print_pwr_info:[RX, TX]: gear=[1, 1], lane[1, 1], pwr[SLOWAUTO_MODE, SLOWAUTO_MODE], rate = 0 [ 2.256240] ufshcd_wait_for_dev_cmd: time_left=8 [ 2.266734] ufshcd_wait_for_dev_cmd = 0 This command succeeds. [ 3.780315] ufshcd_wait_for_dev_cmd: time_left=0 [ 3.780484] ufshcd-qcom 1da4000.ufshc: ufshcd_wait_for_dev_cmd: dev_cmd request timedout, tag 31 [ 3.784258] ufshcd_wait_for_dev_cmd = -11 [ 3.792949] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag: Sending flag query for idn 1 failed, err = -11 [ 3.796936] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag_retry: failed with error -11, retries 0 [ 3.872239] ufshcd-qcom 1da4000.ufshc: ufshcd_update_uic_error: UIC error flags = 0x00000000 [ 3.935871] ufshcd-qcom 1da4000.ufshc: ufshcd_update_uic_error: UIC error flags = 0x00000000 [ 4.006340] ufshcd-qcom 1da4000.ufshc: ufshcd_update_uic_error: UIC error flags = 0x00000001 [ 5.316263] ufshcd_wait_for_dev_cmd: time_left=0 [ 5.316406] ufshcd-qcom 1da4000.ufshc: ufshcd_wait_for_dev_cmd: dev_cmd request timedout, tag 31 [ 5.320177] ufshcd_wait_for_dev_cmd = -11 [ 5.328838] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag: Sending flag query for idn 1 failed, err = -11 [ 5.332872] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag_retry: failed with error -11, retries 1 [ 6.852272] ufshcd_wait_for_dev_cmd: time_left=0 [ 6.852415] ufshcd-qcom 1da4000.ufshc: ufshcd_wait_for_dev_cmd: dev_cmd request timedout, tag 31 [ 6.856185] ufshcd_wait_for_dev_cmd = -11 [ 6.864846] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag: Sending flag query for idn 1 failed, err = -11 [ 6.868872] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag_retry: failed with error -11, retries 2 [ 6.878415] ufshcd-qcom 1da4000.ufshc: ufshcd_query_flag_retry: query attribute, opcode 6, idn 1, failed with error -11 after 3 retires [ 6.887258] ufshcd-qcom 1da4000.ufshc: ufshcd_complete_dev_init setting fDeviceInit flag failed with error -11 [ 6.900929] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: core_clk disabled [ 6.909171] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: bus_aggr_clk disabled [ 6.917054] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: iface_clk disabled [ 6.925112] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: core_clk_unipro disabled [ 6.932849] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: core_clk_ice disabled [ 6.941305] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: ref_clk disabled [ 6.949346] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: tx_lane0_sync_clk disabled [ 6.956721] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: rx_lane0_sync_clk disabled [ 6.965405] ufshcd-qcom 1da4000.ufshc: __ufshcd_setup_clocks: clk: rx_lane1_sync_clk disabled It's strange that one command succeeds, and the 3 next fail... Maybe they don't speak to the same HW block... Regards.
