Benchmark example by puuu · Pull Request #2 · janLo/ArduinoSimpleLogging · GitHub
Skip to content

Benchmark example#2

Open
puuu wants to merge 1 commit into
janLo:masterfrom
puuu:benchmark
Open

Benchmark example#2
puuu wants to merge 1 commit into
janLo:masterfrom
puuu:benchmark

Conversation

@puuu

@puuu puuu commented Dec 18, 2017

Copy link
Copy Markdown
Contributor

Hi, I did some benchmarking of this lib. Writing single bytes or PROGMEM is rather slow compared to String. In addition, as a poc, I tried to implement a prebuffer to avoid iteration of all handler in ArduinoSimpleLogging::log(). You can find it in my prebuffer branch (puuu/ArduinoSimpleLogging@dd8cef7). The benchmark results (see below), show no big improvement (may be for a high number of handler, but this is unlikely a use case). Thus, the iteration is not the problem. The overhead likely comes from the dynamic binding within the Print class.

Anyhow, the benchmark example can be helpful.

Original:

------------------------
No Handler ...
char string
duration 4311 us, 0 calls
single chars
duration 20594 us, 0 calls
PROGMEM string
duration 25170 us, 0 calls
String object
duration 2971 us, 0 calls
------------------------

------------------------
Handler for error, logging to debug ...
char string
duration 4526 us, 0 calls
single chars
duration 24075 us, 0 calls
PROGMEM string
duration 28651 us, 0 calls
String object
duration 3214 us, 0 calls
------------------------

------------------------
Handler for error, logging to error ...
char string
duration 4905 us, 2 calls
single chars
duration 29326 us, 28 calls
PROGMEM string
duration 33901 us, 28 calls
String object
duration 3588 us, 2 calls
------------------------

Prebuffer

------------------------
No Handler ...
char string
duration 4436 us, 0 calls
single chars
duration 25311 us, 0 calls
PROGMEM string
duration 29820 us, 0 calls
String object
duration 3096 us, 0 calls
------------------------

------------------------
Handler for error, logging to debug ...
char string
duration 4651 us, 0 calls
single chars
duration 25539 us, 0 calls
PROGMEM string
duration 30176 us, 0 calls
String object
duration 3338 us, 0 calls
------------------------

------------------------
Handler for error, logging to error ...
char string
duration 5030 us, 2 calls
single chars
duration 25914 us, 2 calls
PROGMEM string
duration 30739 us, 3 calls
String object
duration 3714 us, 2 calls
------------------------

@janLo

janLo commented Dec 18, 2017

Copy link
Copy Markdown
Owner

@puuu

puuu commented Dec 20, 2017

Copy link
Copy Markdown
Contributor Author

The idea of this example is to see what impact any code change has to this library.
With this I realised that buffering will not increase the performance. I showed the output of the prebuffer brnach only to share this experience.

Now I added an output of the time used by the PrintMock:

------------------------
Only the the handler ...
char string
duration 3295 us, 2 calls
single chars
duration 9034 us, 28 calls
PROGMEM string
duration 13561 us, 28 calls
String object
duration 1996 us, 2 calls
------------------------

------------------------
No Handler ...
char string
duration 4263 us, 0 calls
single chars
duration 20588 us, 0 calls
PROGMEM string
duration 25150 us, 0 calls
String object
duration 2963 us, 0 calls
------------------------

------------------------
Handler for error, logging to debug ...
char string
duration 4501 us, 0 calls
single chars
duration 24076 us, 0 calls
PROGMEM string
duration 28651 us, 0 calls
String object
duration 3214 us, 0 calls
------------------------

------------------------
Handler for error, logging to error ...
char string
duration 4876 us, 2 calls
single chars
duration 29326 us, 28 calls
PROGMEM string
duration 33901 us, 28 calls
String object
duration 3588 us, 2 calls
------------------------

You can now subtract them from the time of your Logger:

No Handler Not matching Handler Matching Handler
char 968 1206 1581
single chars 11554 15042 20292
PROGMEM 11589 15090 20340
String 967 1218 1592

From this you see that the char and String have almost the same overhead as well as single chars and PROGMEM. But the total times are still important, since they tell how the lib performance compared to a preprocessed controlled logger.

Anyhow, at the moment I do not see a way to optimize the speed of this lib further more. And if you log to Serial then, the overhead of this lib is negligible.

By the way, all test were performed with a WeMos D1 mini at 80 MHz.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants