On 12/4/2018 8:23 AM, Marc Gonzalez wrote:
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...
Throwing something at a wall and seeing if it sticks....
The downstream MTP dtsi has -
&ufsphy1 {
vdda-phy-supply = <&pm8998_l1>;
vdda-pll-supply = <&pm8998_l2>;
vddp-ref-clk-supply = <&pm8998_l26>;
vdda-phy-max-microamp = <51400>;
vdda-pll-max-microamp = <14600>;
vddp-ref-clk-max-microamp = <100>;
vddp-ref-clk-always-on;
status = "ok";
};
&ufs1 {
vdd-hba-supply = <&gdsc_ufs>;
vdd-hba-fixed-regulator;
vcc-supply = <&pm8998_l20>;
vccq-supply = <&pm8998_l26>;
vccq2-supply = <&pm8998_s4>;
vcc-max-microamp = <750000>;
vccq-max-microamp = <560000>;
vccq2-max-microamp = <750000>;
status = "ok";
};
The *-max-microamp fields are basically load values that the downstream
driver sets on the regulators to ensure they are in a performance mode
before the driver attempts normal operation.
On the corresponding regulators in the mtp dtsi, you might try adding
regulator-allow-set-load;
regulator-system-load = <X>;
It might be that the regulators act as pull ups on some of the
signal/data lines, and by default they are not being driven hard enough
to do that job properly, resulting in the timeouts you see.
--
Jeffrey Hugo
Qualcomm Datacenter Technologies as an affiliate of Qualcomm
Technologies, Inc.
Qualcomm Technologies, Inc. is a member of the
Code Aurora Forum, a Linux Foundation Collaborative Project.
