Synchronize console writes #227

mjcarroll · 2021-06-22T19:48:54Z

Signed-off-by: Michael Carroll michael@openrobotics.org

🎉 New feature

Summary

Provide an internal mechanism for console writes. This will prevent messages from being interleaved.

Test it

Checklist

Signed all commits for DCO
Added tests
Added example and/or tutorial
Updated documentation (as needed)
Updated migration guide (as needed)
codecheck passed (See contributing)
All tests passed (See test coverage)
While waiting for a review on your PR, please help review another open pull request to support the maintainers

Note to maintainers: Remember to use Squash-Merge

codecov · 2021-06-22T19:57:51Z

Codecov Report

Merging #227 (2dd8bdd) into ign-common4 (b337f4e) will increase coverage by 0.03%.
The diff coverage is 100.00%.

@@               Coverage Diff               @@
##           ign-common4     #227      +/-   ##
===============================================
+ Coverage        77.07%   77.10%   +0.03%     
===============================================
  Files               75       75              
  Lines            10679    10694      +15     
===============================================
+ Hits              8231     8246      +15     
  Misses            2448     2448

Impacted Files	Coverage Δ
src/Console.cc	`86.13% <100.00%> (+1.33%)`	⬆️
src/Util.cc	`84.00% <100.00%> (+0.24%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update b337f4e...2dd8bdd. Read the comment docs.

chapulina

I'd be interested in knowing how this affects performance.

Also, this could be targeted at ign-common3, right?

chapulina · 2021-07-20T16:42:52Z

src/Console.cc

-  Console::log << outstr;
-  Console::log.flush();
+  {
+    std::lock_guard<std::mutex> lk(syncMutex);


Did you consider having separate mutexes for logging to disk and logging to the console? This way different loggers could write to disk and to console at the same time. It may be a small optimization, but when logging a lot it could make a difference?

mjcarroll · 2021-07-20T16:48:18Z

I'd be interested in knowing how this affects performance.

I agree. We don't have any metric for console performance right now, so it's a bit handwavy.

Signed-off-by: Michael Carroll <michael@openrobotics.org>

https://gist.github.com/KjellKod/4d88035f9af513eed69e Signed-off-by: Michael Carroll <michael@openrobotics.org>

mjcarroll · 2021-07-20T18:18:55Z

I copied this latency test from a spdlog test I found: https://gist.github.com/KjellKod/4d88035f9af513eed69e

All times are in microseconds:

Without the mutex:

Num Threads: 1, Min: 3.0, Max: 742230.0, Mean: 6.500559, Median: 5.0
Num Threads: 2, Min: 2.0, Max: 134537.0, Mean: 15.518016, Median: 15.0
Num Threads: 4, Min: 2.0, Max: 103224.0, Mean: 32.359236, Median: 43.0
Num Threads: 8, Min: 2.0, Max: 59725.0, Mean: 68.890648, Median: 107.0
Num Threads: 16, Min: 2.0, Max: 57508.0, Mean: 140.911656, Median: 249.0
Num Threads: 32, Min: 2.0, Max: 56070.0, Mean: 285.820097, Median: 536.0

With the mutex:

Num Threads: 1, Min: 3.0, Max: 836221.0, Mean: 6.156619, Median: 4.0
Num Threads: 2, Min: 3.0, Max: 183572.0, Mean: 18.738199, Median: 17.0
Num Threads: 4, Min: 2.0, Max: 64967.0, Mean: 38.969061, Median: 52.0
Num Threads: 8, Min: 2.0, Max: 55175.0, Mean: 85.129123, Median: 137.0
Num Threads: 16, Min: 2.0, Max: 52507.0, Mean: 169.010793, Median: 292.0
Num Threads: 32, Min: 2.0, Max: 50190.0, Mean: 336.777897, Median: 602.0

azeey · 2021-08-06T15:54:18Z

I found more data races with TSAN and opened a PR suggesting chagnes: #237

* More data race fixes Signed-off-by: Addisu Z. Taddese <addisu@openrobotics.org> Co-authored-by: Alejandro Hernández Cordero <ahcorde@gmail.com>

azeey

LGTM! Since I wrote part of this PR, another pair of eyes might be good.

test/performance/logging.cc

azeey · 2021-08-23T16:52:31Z

The ABI check is not happy because of the new Logger::Buffer::xsputn override and the Logger::Buffer::syncMutex member. Technically, this is true, but Logger::Buffer is an internal class and should not be instantiated by users, so I don't think it's a true ABI break.

chapulina · 2021-08-23T21:46:30Z

Logger::Buffer is an internal class and should not be instantiated by users

I'm not sure if that's true. The Logger class has virtual members, which implies that it's meant to be extended. Derived classes would have access to Buffer, right?

azeey · 2021-08-23T23:37:10Z

I'm not sure if that's true. The Logger class has virtual members, which implies that it's meant to be extended. Derived classes would have access to Buffer, right?

So...it looks like Logger::rdbuf returns a pointer the Buffer object, so yeah, any type of user, not just derived classes, would have access to Buffer. Adding a new override would break ABI 😢. But if we can't override xsputn, I don't know how we can prevent a race condition on the internal std::string buffer.

chapulina · 2021-09-10T16:28:10Z

But if we can't override xsputn, I don't know how we can prevent a race condition on the internal std::string buffer.

Looking at the ABI report again, it looks like the only issue is the new mutex. Can we do the static map trick to avoid adding the member variable?

Signed-off-by: Nate Koenig <nate@openrobotics.org>

nkoenig · 2021-10-15T00:03:25Z

Static map used in b08f53a

azeey · 2021-10-15T02:31:06Z

Thanks @nkoenig for adding the map. My concern with using a global variable is that it violates the GSG guideline about objects of static duration that have non-trivial destructors. I would vote for making the map a function-local static variable that gets allocated on the heap and never gets deleted. I know this would cause errors when running under a memory profiler, but I think it's worth it to avoid the potential bugs that can be caused by having the map be a global variable.

nkoenig · 2021-10-15T03:23:33Z

Thanks @nkoenig for adding the map. My concern with using a global variable is that it violates the GSG guideline about objects of static duration that have non-trivial destructors. I would vote for making the map a function-local static variable that gets allocated on the heap and never gets deleted. I know this would cause errors when running under a memory profiler, but I think it's worth it to avoid the potential bugs that can be caused by having the map be a global variable.

Sounds good. I'll step aside, and let you or someone else take the wheel.

Signed-off-by: Michael Carroll <michael@openrobotics.org>

mjcarroll · 2021-11-09T14:03:48Z

@azeey ready for another look, switched to function local static map pointer.

azeey

LGTM! Checked with TSAN. Just a few nits

azeey · 2021-11-09T17:57:42Z

src/Console.cc

@@ -14,6 +14,7 @@
 * limitations under the License.
 *
 */
+#include <map>


nit: Should this be unordered_map since that's what we're using in BufferLock?

src/Console.cc

azeey · 2021-11-11T18:09:46Z

Are we planning to backport this to citadel?

Signed-off-by: Michael Carroll <michael@openrobotics.org>

azeey · 2021-11-15T18:27:26Z

Probably need to increase the timeout on the test. I think that's why windows CI is failing.

Signed-off-by: Michael Carroll <michael@openrobotics.org>

mjcarroll · 2021-11-15T18:51:48Z

Probably need to increase the timeout on the test. I think that's why windows CI is failing.

Done, it looks like we are only failing in the plugin specialization test, which is known flaky.

Add PBR material class Signed-off-by: Michael Carroll <michael@openrobotics.org>

osrf-triage · 2022-01-25T01:01:08Z

This pull request has been mentioned on Gazebo Community. There might be relevant details there:

https://community.gazebosim.org/t/new-ignition-releases-2022-01-24-citadel-edifice-fortress/1241/1

Provide an internal mechanism for console writes. This will prevent messages from being interleaved. Signed-off-by: Michael Carroll <michael@openrobotics.org> Co-authored-by: Addisu Z. Taddese <addisu@openrobotics.org> Co-authored-by: Alejandro Hernández Cordero <ahcorde@gmail.com> Co-authored-by: Nate Koenig <nate@openrobotics.org>

mjcarroll requested a review from azeey June 22, 2021 19:48

github-actions bot added 🏢 edifice Ignition Edifice 🏯 fortress Ignition Fortress labels Jun 22, 2021

azeey mentioned this pull request Jun 30, 2021

👨‍🌾 Add a potential temporary fix for flaky tests on macOS gazebosim/gz-sim#807

Closed

7 tasks

mjcarroll marked this pull request as ready for review July 20, 2021 14:34

chapulina reviewed Jul 20, 2021

View reviewed changes

mjcarroll added 2 commits July 20, 2021 13:03

Syncronize console writes

fe760ab

Signed-off-by: Michael Carroll <michael@openrobotics.org>

Add latency testing from unlicensed code

2658fd0

https://gist.github.com/KjellKod/4d88035f9af513eed69e Signed-off-by: Michael Carroll <michael@openrobotics.org>

mjcarroll force-pushed the lock_console branch from 6c205f3 to 2658fd0 Compare July 20, 2021 18:17

chapulina self-requested a review July 26, 2021 18:09

Suggestion to #227: More data race fixes (#237)

d7601bd

* More data race fixes Signed-off-by: Addisu Z. Taddese <addisu@openrobotics.org> Co-authored-by: Alejandro Hernández Cordero <ahcorde@gmail.com>

azeey approved these changes Aug 23, 2021

View reviewed changes

test/performance/logging.cc Show resolved Hide resolved

chapulina added the beta Targeting beta release of upcoming collection label Sep 8, 2021

Merge branch 'ign-common4' into lock_console

3408a0d

chapulina removed the beta Targeting beta release of upcoming collection label Sep 20, 2021

Use static map to avodi ABI breakage

b08f53a

Signed-off-by: Nate Koenig <nate@openrobotics.org>

nkoenig approved these changes Oct 15, 2021

View reviewed changes

mjcarroll added 2 commits November 9, 2021 08:02

Switch to function local static

a7e8fed

Signed-off-by: Michael Carroll <michael@openrobotics.org>

Merge branch 'ign-common4' into lock_console

f5097ce

azeey approved these changes Nov 9, 2021

View reviewed changes

Address reviewer feedback

7e8b1a0

Signed-off-by: Michael Carroll <michael@openrobotics.org>

Lower iteration numbers to keep CI fresh

2dd8bdd

Signed-off-by: Michael Carroll <michael@openrobotics.org>

azeey approved these changes Nov 18, 2021

View reviewed changes

mjcarroll merged commit d93da52 into ign-common4 Nov 18, 2021

mjcarroll deleted the lock_console branch November 18, 2021 22:52

scpeters pushed a commit to scpeters/ign-common that referenced this pull request Jan 19, 2022

Merged in pbr_common3 (pull request gazebosim#227)

edb6d0f

Add PBR material class Signed-off-by: Michael Carroll <michael@openrobotics.org>

chapulina mentioned this pull request Apr 1, 2022

Use ign-common console gazebosim/sdformat#928

Closed

8 tasks

azeey mentioned this pull request Jun 24, 2022

Fix race condition in FileLogger #378

Merged

8 tasks

azeey mentioned this pull request Jun 24, 2022

Backport: Synchronize console (#227) and FileLogger (#378) writes #379

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Synchronize console writes #227

Synchronize console writes #227

mjcarroll commented Jun 22, 2021 •

edited

Loading

codecov bot commented Jun 22, 2021 •

edited

Loading

chapulina left a comment

chapulina Jul 20, 2021

mjcarroll commented Jul 20, 2021

mjcarroll commented Jul 20, 2021

azeey commented Aug 6, 2021

azeey left a comment

azeey commented Aug 23, 2021

chapulina commented Aug 23, 2021

azeey commented Aug 23, 2021

chapulina commented Sep 10, 2021

nkoenig commented Oct 15, 2021

azeey commented Oct 15, 2021

nkoenig commented Oct 15, 2021

mjcarroll commented Nov 9, 2021

azeey left a comment

azeey Nov 9, 2021

mjcarroll Nov 15, 2021

azeey commented Nov 11, 2021

azeey commented Nov 15, 2021

mjcarroll commented Nov 15, 2021

osrf-triage commented Jan 25, 2022

Synchronize console writes #227

Synchronize console writes #227

Conversation

mjcarroll commented Jun 22, 2021 • edited Loading

🎉 New feature

Summary

Test it

Checklist

codecov bot commented Jun 22, 2021 • edited Loading

Codecov Report

chapulina left a comment

Choose a reason for hiding this comment

chapulina Jul 20, 2021

Choose a reason for hiding this comment

mjcarroll commented Jul 20, 2021

mjcarroll commented Jul 20, 2021

azeey commented Aug 6, 2021

azeey left a comment

Choose a reason for hiding this comment

azeey commented Aug 23, 2021

chapulina commented Aug 23, 2021

azeey commented Aug 23, 2021

chapulina commented Sep 10, 2021

nkoenig commented Oct 15, 2021

azeey commented Oct 15, 2021

nkoenig commented Oct 15, 2021

mjcarroll commented Nov 9, 2021

azeey left a comment

Choose a reason for hiding this comment

azeey Nov 9, 2021

Choose a reason for hiding this comment

mjcarroll Nov 15, 2021

Choose a reason for hiding this comment

azeey commented Nov 11, 2021

azeey commented Nov 15, 2021

mjcarroll commented Nov 15, 2021

osrf-triage commented Jan 25, 2022

mjcarroll commented Jun 22, 2021 •

edited

Loading

codecov bot commented Jun 22, 2021 •

edited

Loading