servo micro is slow to initialize |
|||
Issue description
# sudo servod -b poppy -c poppy_r1_r2.xml -s SNCQ00044
2017-06-30 14:17:39,574 - servod - INFO - Start
2017-06-30 14:17:39,713 - servod - INFO - Found servo, vid: 0x18d1 pid: 0x501a sid: SNCQ00044
2017-06-30 14:17:39,715 - servod - WARNING - Servo device's iserial was unrecognized.
2017-06-30 14:17:39,715 - servod - INFO - Found XML overlay for board poppy
2017-06-30 14:17:39,715 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/servo_micro.xml, None, 0)
2017-06-30 14:17:39,719 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/common.xml, None, 0)
2017-06-30 14:17:39,722 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/uart_common.xml, None, 0)
2017-06-30 14:17:39,731 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/poppy_r1_r2.xml, None, 0)
2017-06-30 14:17:39,743 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/ina2xx.xml, None, 0)
2017-06-30 14:17:39,764 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/servo_poppy_overlay.xml, None, 0)
2017-06-30 14:17:39,765 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/servoflex_v2_r0_p50.xml, None, 0)
2017-06-30 14:17:39,766 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/x86_ec_common.xml, None, 0)
2017-06-30 14:17:39,767 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/ec_common.xml, None, 0)
2017-06-30 14:17:39,770 - SystemConfig - INFO - Loading XML config (/usr/lib64/python2.7/site-packages/servo/data/cr50.xml, None, 0)
2017-06-30 14:17:39,782 - Servod - INFO - Initializing interface 1 to stm32_uart
2017-06-30 14:17:39,782 - Servod - INFO - Suart: interface: {'interface': 0, 'index': 1, 'name': 'stm32_uart'}
2017-06-30 14:17:39,786 - Servod - INFO - /dev/pts/4
2017-06-30 14:17:39,786 - Servod - INFO - Initializing interface 3 to stm32_uart
2017-06-30 14:17:39,786 - Servod - INFO - Suart: interface: {'interface': 3, 'index': 3, 'name': 'stm32_uart'}
2017-06-30 14:17:39,792 - Servod - INFO - /dev/pts/19
2017-06-30 14:17:39,792 - Servod - INFO - Initializing interface 4 to stm32_i2c
2017-06-30 14:17:39,792 - Servod - INFO - Si2cBus: interface: {'interface': 4, 'index': 4, 'name': 'stm32_i2c'}
2017-06-30 14:17:39,795 - Servod - INFO - Initializing interface 6 to ec3po_uart
2017-06-30 14:17:39,804 - EC3PO Interface - INFO - /dev/pts/25
2017-06-30 14:17:39,804 - Servod - INFO - Initializing interface 7 to stm32_uart
2017-06-30 14:17:39,804 - Servod - INFO - Suart: interface: {'interface': 6, 'index': 7, 'name': 'stm32_uart'}
2017-06-30 14:17:39,806 - EC3PO.Console - INFO - /dev/pts/25 - EC Console is being served on /dev/pts/25.
2017-06-30 14:17:39,809 - Servod - INFO - /dev/pts/26
2017-06-30 14:17:39,809 - Servod - INFO - Initializing interface 8 to stm32_uart
2017-06-30 14:17:39,809 - Servod - INFO - Suart: interface: {'interface': 5, 'index': 8, 'name': 'stm32_uart'}
2017-06-30 14:17:39,813 - Servod - INFO - /dev/pts/28
2017-06-30 14:17:39,813 - Servod - INFO - Initializing interface 9 to ec3po_uart
2017-06-30 14:17:39,816 - EC3PO Interface - INFO - /dev/pts/29
2017-06-30 14:17:39,816 - Servod - INFO - Initializing interface 10 to ec3po_uart
2017-06-30 14:17:39,819 - EC3PO.Console - INFO - /dev/pts/29 - EC Console is being served on /dev/pts/29.
2017-06-30 14:17:39,819 - EC3PO Interface - INFO - /dev/pts/39
2017-06-30 14:17:39,822 - EC3PO.Console - INFO - /dev/pts/39 - EC Console is being served on /dev/pts/39.
Note the timestamps from here: every setting takes 0.5s to initialize:
2017-06-30 14:17:40,330 - Servod - INFO - Initialized uart1_en to on
2017-06-30 14:17:40,852 - Servod - INFO - Initialized servo_jtag_trst to off
2017-06-30 14:17:41,375 - Servod - INFO - Initialized spi1_buf_en to off
2017-06-30 14:17:41,940 - Servod - INFO - Initialized spi2_buf_en to off
2017-06-30 14:17:42,512 - Servod - INFO - Initialized uart2_en to on
2017-06-30 14:17:43,645 - Servod - INFO - Initialized spi1_vref to off
2017-06-30 14:17:44,723 - Servod - INFO - Initialized spi2_vref to off
2017-06-30 14:17:45,277 - Servod - INFO - Initialized servo_jtag_trst_dir to off
2017-06-30 14:17:45,796 - Servod - INFO - Initialized servo_jtag_tdi_dir to off
2017-06-30 14:17:46,348 - Servod - INFO - Initialized gpio_expander_reset to off
2017-06-30 14:17:46,921 - Servod - INFO - Initialized uart3_on_spi1 to off
2017-06-30 14:17:47,477 - Servod - INFO - Initialized SERVO_JTAG_TMS_DIR to off
2017-06-30 14:17:48,508 - Servod - INFO - Initialized SERVO_JTAG_TDO_SEL to off
2017-06-30 14:17:49,020 - Servod - INFO - Initialized SERVO_JTAG_TMS to off
2017-06-30 14:17:50,017 - Servod - INFO - Initialized UART3_TX_SERVO_JTAG_TCK to off
2017-06-30 14:17:50,545 - Servod - INFO - Initialized UART3_RX_JTAG_BUFFER_TO_SERVO_TDO to off
2017-06-30 14:17:51,431 - Servod - INFO - Initialized SERVO_JTAG_TDO_BUFFER_EN to off
2017-06-30 14:17:51,986 - Servod - INFO - Initialized SERVO_JTAG_TDI to off
2017-06-30 14:17:52,504 - Servod - INFO - Initialized SERVO_JTAG_RTCK to off
2017-06-30 14:17:53,008 - Servod - INFO - Initialized JTAG_BUFOUT_EN_L to off
2017-06-30 14:17:54,038 - Servod - INFO - Initialized JTAG_BUFIN_EN_L to off
2017-06-30 14:17:54,040 - Servod - INFO - Initialized fw_wp_en to off
2017-06-30 14:17:54,041 - Servod - INFO - Initialized tp1 to off
2017-06-30 14:17:54,043 - Servod - INFO - Initialized cold_reset to off
2017-06-30 14:17:54,044 - Servod - INFO - Initialized pwr_button to release
2017-06-30 14:17:54,046 - Servod - INFO - Initialized warm_reset to off
2017-06-30 14:17:54,049 - Servod - INFO - Initialized rec_mode to off
2017-06-30 14:17:54,050 - Servod - INFO - Initialized fw_up to off
2017-06-30 14:17:54,051 - Servod - INFO - Initialized lid_open to yes
2017-06-30 14:17:54,054 - Servod - INFO - Initialized pch_disable to off
2017-06-30 14:17:54,055 - Servod - INFO - Initialized tp2 to off
2017-06-30 14:17:54,055 - Servod - INFO - Initialized servo_ec3po_interp_connect to on
2017-06-30 14:17:54,056 - Servod - INFO - Initialized ec_ec3po_interp_connect to on
2017-06-30 14:17:54,056 - Servod - INFO - Initialized usbpd_ec3po_interp_connect to on
2017-06-30 14:17:54,056 - Servod - INFO - Initialized cr50_ec3po_interp_connect to on
2017-06-30 14:17:54,056 - Servod - ERROR - Getting uart4_on_flex_en: 'NoneType' object has no attribute 'wr_rd'
2017-06-30 14:17:54,056 - Servod - ERROR - Problem initializing uart4_on_flex_en -> on :: 'NoneType' object has no attribute 'wr_rd'
2017-06-30 14:17:54,056 - Servod - ERROR - Unable to determine driver for jtag_buf_en
2017-06-30 14:17:54,056 - Servod - ERROR - Problem initializing jtag_buf_en -> on :: 'drv' key not found in params dict
2017-06-30 14:17:58,786 - Servod - INFO - Initialized usbpd_uart_routing to glados
2017-06-30 14:17:58,787 - servod - INFO - Listening on localhost port 9999
,
Jul 3 2017
It's most likely the terminal freezer, but I haven't done any profiling to determine exactly which part is taking ~500ms.
,
Jul 3 2017
Unfortunately it's actually the terminal freezing call that's slow.
,
Jul 3 2017
The timestamps seem to indicate that it might be looking up PIDs. Actually, it might be the call to `lsof` :( Not sure if there's any faster way. I wonder if maybe we can make a way to set them in a "batch".
,
Jul 3 2017
fuser seems a little faster (but does not print out Parent PID): drinkcat@drinkcat:~$ time fuser /dev/pts/48 /dev/pts/48: 4399 4693 real 0m0.161s user 0m0.048s sys 0m0.108s drinkcat@drinkcat:~$ time lsof -FR /dev/pts/48 p4399 R40232 p4693 R4399 real 0m0.386s user 0m0.104s sys 0m0.280s But yeah, batching all the calls is a smarter way...
,
Jul 3 2017
,
Jul 3 2017
Unfortunately the calls are as batched as they can be under the servod architecture, which requires a separate read/write per dut-control. It may make sense to reroute the characters in ec3po into a new internal only pty rather than freezing and redirecting the external one.
,
Nov 20 2017
Any update on this?
,
Nov 20 2017
no. maybe an intern project?
,
Mar 20 2018
Fixed in: https://chromium-review.googlesource.com/c/chromiumos/platform/ec/+/958128 |
|||
►
Sign in to add a comment |
|||
Comment 1 by drinkcat@chromium.org
, Jun 30 2017Logs with --debug enabled, for one control only: 2017-06-30 14:34:17,651 - Servod - DEBUG - servo_server.py:945:get - name(SERVO_JTAG_TMS_DIR) 2017-06-30 14:34:17,651 - Servod - DEBUG - servo_server.py:549:_get_param_drv - 2017-06-30 14:34:17,651 - Servod - DEBUG - servo_server.py:588:_get_param_drv - Using default interface parameter. 2017-06-30 14:34:17,651 - Driver - DEBUG - hw_driver.py:67:__init__ - 2017-06-30 14:34:17,651 - EC3PO Interface - DEBUG - ec3po_interface.py:103:get_pty - get_pty 2017-06-30 14:34:17,651 - Driver - DEBUG - ec3po_gpio.py:74:__init__ - 2017-06-30 14:34:17,651 - Driver - DEBUG - hw_driver.py:119:get - 2017-06-30 14:34:18,114 - Terminal Freezer (/dev/pts/25) - DEBUG - terminal_freezer.py:55:__enter__ - servod processes: ['11088', '11104', '11088', '11109', '11088', '11110', '11088', '11111', '11088', '11112', '11088'] 2017-06-30 14:34:18,114 - Terminal Freezer (/dev/pts/25) - DEBUG - terminal_freezer.py:62:__enter__ - Sending SIGSTOP to process 35453! 2017-06-30 14:34:18,134 - Driver - DEBUG - pty_driver.py:52:_open - opening /dev/pts/25 2017-06-30 14:34:18,137 - EC3PO.Console - DEBUG - console.py:831:StartLoop - /dev/pts/25 - Input from user 2017-06-30 14:34:18,137 - EC3PO.Interpreter - DEBUG - interpreter.py:318:SendCmdToEC - /dev/pts/19 - Removing EC UART from writers. 2017-06-30 14:34:18,138 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->' ' 2017-06-30 14:34:18,138 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'> ' 2017-06-30 14:34:18,150 - EC3PO.Console - DEBUG - console.py:831:StartLoop - /dev/pts/25 - Input from user 2017-06-30 14:34:18,151 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'g' 2017-06-30 14:34:18,151 - EC3PO.Console - DEBUG - console.py:831:StartLoop - /dev/pts/25 - Input from user 2017-06-30 14:34:18,151 - EC3PO.Interpreter - DEBUG - interpreter.py:318:SendCmdToEC - /dev/pts/19 - Removing EC UART from writers. 2017-06-30 14:34:18,152 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'p' 2017-06-30 14:34:18,153 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'i' 2017-06-30 14:34:18,153 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'o' 2017-06-30 14:34:18,153 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'g' 2017-06-30 14:34:18,154 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'e' 2017-06-30 14:34:18,154 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'t' 2017-06-30 14:34:18,154 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->' ' 2017-06-30 14:34:18,155 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'S' 2017-06-30 14:34:18,155 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'E' 2017-06-30 14:34:18,155 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'R' 2017-06-30 14:34:18,156 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'V' 2017-06-30 14:34:18,156 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'O' 2017-06-30 14:34:18,156 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'_' 2017-06-30 14:34:18,157 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'J' 2017-06-30 14:34:18,157 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'T' 2017-06-30 14:34:18,157 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'A' 2017-06-30 14:34:18,158 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'G' 2017-06-30 14:34:18,158 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'_' 2017-06-30 14:34:18,158 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'T' 2017-06-30 14:34:18,159 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'M' 2017-06-30 14:34:18,159 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'S' 2017-06-30 14:34:18,159 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'_' 2017-06-30 14:34:18,160 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'D' 2017-06-30 14:34:18,160 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'I' 2017-06-30 14:34:18,160 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->'R' 2017-06-30 14:34:18,161 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->' ' 2017-06-30 14:34:18,161 - EC3PO.Console - DEBUG - console.py:851:StartLoop - /dev/pts/25 - |DBG|->' 0 O L SERVO_JTAG_TMS_DIR ' 2017-06-30 14:34:18,161 - Driver - DEBUG - pty_driver.py:148:_issue_cmd_get_results - Sent cmds: gpioget SERVO_JTAG_TMS_DIR 2017-06-30 14:34:18,162 - Driver - DEBUG - pty_driver.py:158:_issue_cmd_get_results - Result: (' 0 O L SERVO_JTAG_TMS_DIR', '0') 2017-06-30 14:34:18,162 - Terminal Freezer (/dev/pts/25) - DEBUG - terminal_freezer.py:72:__exit__ - Sending SIGCONT to process 35453! 2017-06-30 14:34:18,162 - SystemConfig - DEBUG - system_config.py:345:_lookup - lookup of map onoff 2017-06-30 14:34:18,162 - Servod - DEBUG - servo_server.py:954:get - SERVO_JTAG_TMS_DIR = off 2017-06-30 14:34:18,162 - Servod - INFO - servo_server.py:1038:hwinit - Initialized SERVO_JTAG_TMS_DIR to off