Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Crash when performance tracking in multiple threads #790

Open
samuel02 opened this issue Jun 5, 2021 · 0 comments · May be fixed by #796
Open

Crash when performance tracking in multiple threads #790

samuel02 opened this issue Jun 5, 2021 · 0 comments · May be fixed by #796

Comments

@samuel02
Copy link

samuel02 commented Jun 5, 2021

Implementation

#include "easylogging++/easylogging++.h"

INITIALIZE_EASYLOGGINGPP

#define THREAD_COUNT 5

int main(void) {
    std::thread threads[THREAD_COUNT];

    for (int i = 0; i < THREAD_COUNT; i++) {
        threads[i] = std::thread([]() {
            for (int i = 0; i < 1000000; i++) {
                TIMED_FUNC(timerObj);
                LOG(DEBUG) << "foo: " << i;
            }
        });
    }

    for (auto&& t : threads) t.join();
}

Compilation

$ g++ --version
g++ (Ubuntu 10.3.0-1ubuntu1) 10.3.0
Copyright (C) 2020 Free Software Foundation, Inc.
This is free software; see the source for copying conditions.  There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
$ g++ -o main -g -std=c++11 -pthread -DELPP_THREAD_SAFE -DELPP_FEATURE_PERFORMANCE_TRACKING -I. main.cpp easylogging++/easylogging++.cc

GDB

GNU gdb (Ubuntu 10.1-2ubuntu2) 10.1.90.20210411-git
Copyright (C) 2021 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from main...
(gdb) run
Starting program: /home/samuel/src/easylogging-issue/main
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff7a16640 (LWP 119092)]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 0
[New Thread 0x7ffff7215640 (LWP 119093)]
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 1
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 2
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
[New Thread 0x7ffff6a14640 (LWP 119094)]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 0
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 3
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
[New Thread 0x7ffff6213640 (LWP 119095)]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 0
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 1
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,979 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 4
[New Thread 0x7ffff5a12640 (LWP 119096)]
2021-06-05 12:19:28,979 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 0
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 1
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [1 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 2
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [1 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 0
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 5
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 1
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 2
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 3
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 1
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 6
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 2
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 3
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 4
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 2
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 7
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 3
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 4
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,980 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 5
2021-06-05 12:19:28,980 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 3
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 4
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [1 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 5
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [1 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 8
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [1 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 6
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 4
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 5
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 6
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 9
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 7
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 5
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 6
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 7
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:19:28,981 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 10
2021-06-05 12:19:28,981 INFO Executed [main()::<lambda()>] in [0 ms]
...
2021-06-05 12:16:27,258 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 273979
2021-06-05 12:16:27,258 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:16:27,258 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 273980
2021-06-05 12:16:27,258 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:16:27,258 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 273981
2021-06-05 12:16:27,258 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:16:27,258 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 273982
2021-06-05 12:16:27,258 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:16:27,260 INFO Executed [main()::<lambda()>] in [0 ms]
2021-06-05 12:16:27,260 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 273983
2021-06-05 12:16:27,260 DEBUG [default] [samuel@unknown-host] [main()::<lambda()>] [main.cpp:14] foo: 274873
2021-06-05 12:16:27,260 INFO Executed [main()::<lambda()>] in [0 ms]

Thread 2 "main" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff7a16640 (LWP 118527)]
__memmove_avx_unaligned_erms () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:269
269     ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S: No such file or directory.
(gdb) bt full
#0  __memmove_avx_unaligned_erms () at ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:269
No locals.
#1  0x00007ffff7ed8a78 in std::basic_streambuf<char, std::char_traits<char> >::xsputn(char const*, long) () from /lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#2  0x00007ffff7ecaee4 in std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long) ()
   from /lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#3  0x000055555557576e in el::base::DefaultPerformanceTrackingCallback::handle (this=0x5555555dd060, data=0x7ffff7a15b90) at easylogging++/easylogging++.h:3522
        ss = <incomplete type>
#4  0x000055555556fb48 in el::base::PerformanceTracker::~PerformanceTracker (this=0x7ffff0000b80, __in_chrg=<optimized out>) at easylogging++/easylogging++.cc:2712
        h = {first = "DefaultPerformanceTrackingCallback", second = std::shared_ptr<el::PerformanceTrackingCallback> (use count 5, weak count 0) = {get() = 0x5555555dd060}}
        __for_range = std::unordered_map with 1 element = {["DefaultPerformanceTrackingCallback"] = std::shared_ptr<el::PerformanceTrackingCallback> (use count 5, weak count 0) = {get() = 0x5555555dd060}}
        __for_begin = {<std::__detail::_Node_iterator_base<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<el::PerformanceTrackingCallback> >, true>> = {
            _M_cur = 0x5555555dcf70}, <No data fields>}
        __for_end = {<std::__detail::_Node_iterator_base<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<el::PerformanceTrackingCallback> >, true>> = {
            _M_cur = 0x0}, <No data fields>}
        formattedTime = "0 ms"
        data = {m_performanceTracker = 0x7ffff0000b80, m_formattedTimeTaken = "0 ms", m_dataType = el::PerformanceTrackingData::DataType::Complete, m_firstCheckpoint = false, m_checkpointId = "", m_file = 0x55555559c7bc "", m_line = 0,
          m_func = 0x55555559c7bc ""}
        callback = 0x5555555dd060
        scopedLock = {_M_device = @0x7ffff0000b88}
        scopedLock = {_M_device = <optimized out>}
Python Exception <class 'gdb.error'> value has been optimized out:
        formattedTime =
        data = {m_performanceTracker = <optimized out>, Python Exception <class 'gdb.error'> value has been optimized out:
m_formattedTimeTaken = , m_dataType = <optimized out>, m_firstCheckpoint = <optimized out>, Python Exception <class 'gdb.error'> value has been optimized out:
m_checkpointId = , m_file = <optimized out>, m_line = <optimized out>,
          m_func = <optimized out>}
        callback = <optimized out>
        h = <optimized out>
        __for_range = <optimized out>
        __for_begin = {<std::__detail::_Node_iterator_base<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<el::PerformanceTrackingCallback> >, true>> = {
            _M_cur = <optimized out>}, <No data fields>}
        __for_end = {<std::__detail::_Node_iterator_base<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<el::PerformanceTrackingCallback> >, true>> = {
            _M_cur = <optimized out>}, <No data fields>}
#5  0x000055555556fc32 in el::base::PerformanceTracker::~PerformanceTracker (this=0x7ffff0000b80, __in_chrg=<optimized out>) at easylogging++/easylogging++.cc:2718
        scopedLock = {_M_device = <optimized out>}
Python Exception <class 'gdb.error'> value has been optimized out:
        formattedTime =
        data = {m_performanceTracker = <optimized out>, Python Exception <class 'gdb.error'> value has been optimized out:
m_formattedTimeTaken = , m_dataType = <optimized out>, m_firstCheckpoint = <optimized out>, Python Exception <class 'gdb.error'> value has been optimized out:
m_checkpointId = , m_file = <optimized out>, m_line = <optimized out>,
          m_func = <optimized out>}
        callback = <optimized out>
        h = <optimized out>
        __for_range = <optimized out>
        __for_begin = {<std::__detail::_Node_iterator_base<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<el::PerformanceTrackingCallback> >, true>> = {
            _M_cur = <optimized out>}, <No data fields>}
        __for_end = {<std::__detail::_Node_iterator_base<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::shared_ptr<el::PerformanceTrackingCallback> >, true>> = {
            _M_cur = <optimized out>}, <No data fields>}
#6  0x000055555555e998 in std::default_delete<el::base::PerformanceTracker>::operator() (this=0x7ffff7a15ca8, __ptr=0x7ffff0000b80) at /usr/include/c++/10/bits/unique_ptr.h:85
No locals.
#7  0x000055555555e576 in std::unique_ptr<el::base::PerformanceTracker, std::default_delete<el::base::PerformanceTracker> >::~unique_ptr (this=0x7ffff7a15ca8, __in_chrg=<optimized out>) at /usr/include/c++/10/bits/unique_ptr.h:361
        __ptr = @0x7ffff7a15ca8: 0x7ffff0000b80
        __ptr = <optimized out>
#8  0x000055555555d43d in operator() (__closure=0x5555555ddf98) at main.cpp:13
        timerObj = std::unique_ptr<el::base::PerformanceTracker> = {get() = 0x7ffff0000b80}
        i = 274888
        __PRETTY_FUNCTION__ = "main()::<lambda()>"
#9  0x000055555555dbf2 in std::__invoke_impl<void, main()::<lambda()> >(std::__invoke_other, struct {...} &&) (__f=...) at /usr/include/c++/10/bits/invoke.h:60
No locals.
#10 0x000055555555dba7 in std::__invoke<main()::<lambda()> >(struct {...} &&) (__fn=...) at /usr/include/c++/10/bits/invoke.h:95
No locals.
#11 0x000055555555db54 in std::thread::_Invoker<std::tuple<main()::<lambda()> > >::_M_invoke<0>(std::_Index_tuple<0>) (this=0x5555555ddf98) at /usr/include/c++/10/thread:264
No locals.
#12 0x000055555555db28 in std::thread::_Invoker<std::tuple<main()::<lambda()> > >::operator()(void) (this=0x5555555ddf98) at /usr/include/c++/10/thread:271
No locals.
#13 0x000055555555db0c in std::thread::_State_impl<std::thread::_Invoker<std::tuple<main()::<lambda()> > > >::_M_run(void) (this=0x5555555ddf90) at /usr/include/c++/10/thread:215
No locals.
#14 0x00007ffff7e6d694 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
No symbol table info available.
#15 0x00007ffff7d5f450 in start_thread (arg=0x7ffff7a16640) at pthread_create.c:473
        ret = <optimized out>
        pd = 0x7ffff7a16640
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737347937856, 8910282846276004542, 140737488342014, 140737488342015, 0, 140737347937856, -8910301182618391874, -8910300798842721602}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0,
              0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = 0
#16 0x00007ffff7c81d53 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.
(gdb)

The error only occurs when running the loop in multiple threads.
@bloom256 bloom256 linked a pull request Sep 7, 2021 that will close this issue
Open
7 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

mutex was made static to fix performace tracker bloom256/easyloggingpp
1 participant
@samuel02