Fix pigweed RPC logging on ESP32 #26282

tehampson · 2023-04-27T17:29:49Z

Regression introduced in #26227. After that PR we no longer get matter logs in pigweed RPC. This reverts src/platform/ESP32/Logging.cpp to before the regression. Not only is it matter logging broken, but the changes also caused some back to back RPC calls to hang and timeout.

Test:

Compiled using ./scripts/build/build_examples.py --target esp32-m5stack-all-clusters-rpc build.
Flashed onto M5Stack using ./out/esp32-m5stack-all-clusters-rpc/chip-all-clusters-app.flash.py
Attached to pigweed rpc console python3 -m chip_rpc.console --device /dev/ttyUSB0
Confirmed
- That we are getting chip logs again
- Confirmed that doing multiple back to backrpcs.chip.rpc.Device.SetPairingState(pairing_enabled=False) and rpcs.chip.rpc.Device.SetPairingState(pairing_enabled=True) does not result in a timeout

src/platform/ESP32/Logging.cpp

github-actions · 2023-04-27T17:44:22Z

PR #26282: Size comparison from 5a68477 to 3940f15

Increases (1 build for cc32xx)

platform	target	config	section	`5a68477`	`3940f15`	change	% change
cc32xx	lock	CC3235SF_LAUNCHXL	.debug_info	19489249	19489251	2	0.0

Full report (1 build for cc32xx)

platform	target	config	section	`5a68477`	`3940f15`	change
cc32xx	lock	CC3235SF_LAUNCHXL		0	0	0
			(read only)	601114	601114	0
			(read/write)	204132	204132	0
			.ARM.attributes	44	44	0
			.ARM.exidx	8	8	0
			.bss	197544	197544	0
			.comment	206	206	0
			.data	1468	1468	0
			.debug_abbrev	956756	956756	0
			.debug_aranges	103416	103416	0
			.debug_frame	349704	349704	0
			.debug_info	19489249	19489251	2
			.debug_line	2678035	2678035	0
			.debug_line_str	513	513	0
			.debug_loc	33340	33340	0
			.debug_loclists	1501882	1501882	0
			.debug_ranges	4984	4984	0
			.debug_rnglists	96008	96008	0
			.debug_str	3024877	3024877	0
			.ramVecs	780	780	0
			.resetVecs	64	64	0
			.rodata	104170	104170	0
			.shstrtab	265	265	0
			.stack	2048	2048	0
			.strtab	477531	477531	0
			.symtab	285936	285936	0
			.text	494824	494824	0

andy31415 · 2023-04-27T17:44:44Z

@dhrishi any chance you could look at this and advise on how to use these things?

dhrishi · 2023-04-28T12:07:28Z

This PR also changes the default of the newly introduced DISPATCH_EVENT_LONG_DISPATCH_TIME_WARNING_THRESHOLD_MS to match the default in the SDK, which is 100ms. Having a lower default will more likely help people catch real issues as the dispatcher should not be taking 100ms to start with. If there is a project that needs a higher threshold it would make sense for that individual project to use a higher value.

I had taken a look at the origin of DISPATCH_EVENT_LONG_DISPATCH_TIME_WARNING_THRESHOLD_MS and it was there from the legacy code. Apart from printing the error message, it does not do anything like propagating it or taking some action (for any platform).
The change here was induced to provide an option to the application to set the threshold as per their requirement. Also, it resulted into large number of error prints on the console .
Even though the default is set to 700, you can always set it to a lower value in the application.

tehampson · 2023-04-28T12:15:24Z

I had taken a look at the origin of DISPATCH_EVENT_LONG_DISPATCH_TIME_WARNING_THRESHOLD_MS and it was there from the legacy code. Apart from printing the error message, it does not do anything like propagating it or taking some action (for any platform).
The change here was induced to provide an option to the application to set the threshold as per their requirement. Also, it resulted into large number of error prints on the console .
Even though the default is set to 700, you can always set it to a lower value in the application.

Thing taking 500ms to dispatch is likely going to have downstream impacts. Now when someone looks at a log they are going have that context by default and spend more time, IMO potentially looking into the wrong thing. If any application find this log spammy, and they know that it is not an issue for their application, that application should use a higher value. How I see it you can start masking an issue that can progressively get worse over time. But if this is the default that your platform wants to give I will remove that part of the PR

dhrishi · 2023-04-28T12:37:36Z

How I see it you can start masking an issue that can progressively get worse over time. But if this is the default that your platform wants to give I will remove that part of the PR

IMO, serving a particular event can take time depending on the type of action it does and depending on the network. In short, as per our experiments, if one request takes some time then it does not mean that the subsequent requests will always be worse. Did you notice anything otherwise? Also, as I said, this prints error on the console and nothing else which won't be of much help in the production devices

dhrishi · 2023-04-28T12:42:31Z

Having said that, if you feel that the default value is too large, we can decide on some acceptable default value for this and update the same.

src/platform/ESP32/Logging.cpp

dhrishi · 2023-04-28T13:00:07Z

As per my offline discussion with @tehampson , we will revert this and put up a subsequent PR with the fix to Pigweed RPC too as this breaks the Google daily builds. Approving this PR now

config/esp32/components/chip/Kconfig

github-actions · 2023-04-28T14:07:55Z

PR #26282: Size comparison from 5a68477 to 1de144a

Increases above 0.2%:

platform	target	config	section	`5a68477`	`1de144a`	change	% change
cc32xx	lock	CC3235SF_LAUNCHXL	(read only)	601114	602714	1600	0.3
			.debug_aranges	103416	103664	248	0.2
			.debug_frame	349704	350552	848	0.2
			.debug_loclists	1501882	1506147	4265	0.3
			.debug_rnglists	96008	96278	270	0.3
			.debug_str	3024877	3059490	34613	1.1
			.strtab	477531	481887	4356	0.9
			.symtab	285936	287248	1312	0.5
			.text	494824	496340	1516	0.3

Increases (1 build for cc32xx)

platform	target	config	section	`5a68477`	`1de144a`	change	% change
cc32xx	lock	CC3235SF_LAUNCHXL	(read only)	601114	602714	1600	0.3
			(read/write)	204132	204156	24	0.0
			.bss	197544	197568	24	0.0
			.debug_abbrev	956756	956984	228	0.0
			.debug_aranges	103416	103664	248	0.2
			.debug_frame	349704	350552	848	0.2
			.debug_info	19489249	19521972	32723	0.2
			.debug_line	2678035	2682751	4716	0.2
			.debug_loclists	1501882	1506147	4265	0.3
			.debug_rnglists	96008	96278	270	0.3
			.debug_str	3024877	3059490	34613	1.1
			.rodata	104170	104250	80	0.1
			.strtab	477531	481887	4356	0.9
			.symtab	285936	287248	1312	0.5
			.text	494824	496340	1516	0.3

Full report (1 build for cc32xx)

platform	target	config	section	`5a68477`	`1de144a`	change	% change
cc32xx	lock	CC3235SF_LAUNCHXL		0	0	0	0.0
			(read only)	601114	602714	1600	0.3
			(read/write)	204132	204156	24	0.0
			.ARM.attributes	44	44	0	0.0
			.ARM.exidx	8	8	0	0.0
			.bss	197544	197568	24	0.0
			.comment	206	206	0	0.0
			.data	1468	1468	0	0.0
			.debug_abbrev	956756	956984	228	0.0
			.debug_aranges	103416	103664	248	0.2
			.debug_frame	349704	350552	848	0.2
			.debug_info	19489249	19521972	32723	0.2
			.debug_line	2678035	2682751	4716	0.2
			.debug_line_str	513	513	0	0.0
			.debug_loc	33340	33340	0	0.0
			.debug_loclists	1501882	1506147	4265	0.3
			.debug_ranges	4984	4984	0	0.0
			.debug_rnglists	96008	96278	270	0.3
			.debug_str	3024877	3059490	34613	1.1
			.ramVecs	780	780	0	0.0
			.resetVecs	64	64	0	0.0
			.rodata	104170	104250	80	0.1
			.shstrtab	265	265	0	0.0
			.stack	2048	2048	0	0.0
			.strtab	477531	481887	4356	0.9
			.symtab	285936	287248	1312	0.5
			.text	494824	496340	1516	0.3

Basically this unreverts the project-chip#26282 with additional changes to fixed the rpc logging problem introduced in project-chip#26227.

…26348) * [ESP32] Use esp_log_writev() for logging rather than ESP_LOGx macros Basically this unreverts the #26282 with additional changes to fixed the rpc logging problem introduced in #26227. * Fix the bug when setting the log level * remove the log level check * Fix the color codes for pigweed logs * Added comment explaining the addition of color codes in pigweed logger

…roject-chip#26348) * [ESP32] Use esp_log_writev() for logging rather than ESP_LOGx macros Basically this unreverts the project-chip#26282 with additional changes to fixed the rpc logging problem introduced in project-chip#26227. * Fix the bug when setting the log level * remove the log level check * Fix the color codes for pigweed logs * Added comment explaining the addition of color codes in pigweed logger

…26348) (#26477) * [ESP32] Use esp_log_writev() for logging rather than ESP_LOGx macros Basically this unreverts the #26282 with additional changes to fixed the rpc logging problem introduced in #26227. * Fix the bug when setting the log level * remove the log level check * Fix the color codes for pigweed logs * Added comment explaining the addition of color codes in pigweed logger

Revert parts of project-chip#26227

3940f15

github-actions bot added config esp32 platform labels Apr 27, 2023

pullapprove bot requested review from turon, vijs, vivien-apple, woody-apple, xylophone21 and younghak-hwang April 27, 2023 17:30

andy31415 reviewed Apr 27, 2023

View reviewed changes

src/platform/ESP32/Logging.cpp Show resolved Hide resolved

andy31415 approved these changes Apr 27, 2023

View reviewed changes

tehampson commented Apr 28, 2023

View reviewed changes

src/platform/ESP32/Logging.cpp Show resolved Hide resolved

dhrishi approved these changes Apr 28, 2023

View reviewed changes

pullapprove bot added review - approved and removed review - pending labels Apr 28, 2023

tehampson commented Apr 28, 2023

View reviewed changes

config/esp32/components/chip/Kconfig Outdated Show resolved Hide resolved

Address PR comment

1de144a

tehampson merged commit bedffde into project-chip:master Apr 28, 2023

shubhamdp mentioned this pull request May 3, 2023

[ESP32] Use esp_log_writev() for logging rather than ESP_LOGx macros #26348

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix pigweed RPC logging on ESP32 #26282

Fix pigweed RPC logging on ESP32 #26282

tehampson commented Apr 27, 2023 •

edited

Loading

github-actions bot commented Apr 27, 2023

andy31415 commented Apr 27, 2023

dhrishi commented Apr 28, 2023

tehampson commented Apr 28, 2023

dhrishi commented Apr 28, 2023

dhrishi commented Apr 28, 2023

dhrishi commented Apr 28, 2023

github-actions bot commented Apr 28, 2023

Fix pigweed RPC logging on ESP32 #26282

Fix pigweed RPC logging on ESP32 #26282

Conversation

tehampson commented Apr 27, 2023 • edited Loading

github-actions bot commented Apr 27, 2023

andy31415 commented Apr 27, 2023

dhrishi commented Apr 28, 2023

tehampson commented Apr 28, 2023

dhrishi commented Apr 28, 2023

dhrishi commented Apr 28, 2023

dhrishi commented Apr 28, 2023

github-actions bot commented Apr 28, 2023

tehampson commented Apr 27, 2023 •

edited

Loading