Clickhouse: Callstack printing

[kreuzerkrieg]

Dont know why, but file names and line numbers are not printed when the callstack is printed to the console.
Could you please change it?

[alexey-milovidov]

It is possible to implement, but it requires either:

1. Calling a separate program: addr2line or llvm-symbolizer or gdb or lldb. We would either check that the program is installed in system and use it if available or add a dependency for our packages (worse).

2. Directly using LLVM code as llvm-symbolizer does. This is more hard to do but better from usability standpoint. We already link with LLVM.

Also note that finding line numbers is slow (it can take tens of seconds) - it involves parsing debug info. And we have about 1.5 GB of debug info. For this reason, we ship debug info in a separate package (clickhouse-common-static-dbg).

[alexey-milovidov]

Also it's rather easy to add file and line of exact location of throw but it isn't easy for every call stack frame.

[kreuzerkrieg]

Hm... slow search is a good reason to drop that feature... how about google's breakpad? maybe they know to do it in a fast fashion, somehow?

[alexey-milovidov]

We probably can create some index on build time to quickly find file and line from address.
(It won't work for dlopened libraries, but it's fine)

PS. Relevant links:

1. https://github.com/gimli-rs/addr2line/issues/2 https://lib.rs/crates/addr2line
2. https://lore.kernel.org/patchwork/patch/413455/ (we can't use libbfd due to license, but we can implement the same with LLVM).

[kreuzerkrieg]

Thats it, addr2line AFAIR, we have used it once upon a time, but our project was way smaller than CH. Though I dont remember we had a problem with licensing, but what do I know about licensing.

Would you implement it?

[alexey-milovidov]

There is quite a good code with appropriate license:
https://github.com/facebook/folly/blob/master/folly/experimental/symbolizer/Dwarf.h
https://github.com/facebook/folly/blob/master/folly/experimental/symbolizer/Dwarf.cpp
Maybe we can reuse it.

[kreuzerkrieg]

You are walking thin ice. Start with folly symbolizer and you will find yourself rewriting CH threading model to use folly fibers :)

[alexey-milovidov]

I'm trying to add lines printing in my branch https://github.com/yandex/ClickHouse/pull/6201

It will look like this:

2019.07.30 01:43:23.281095 [ 57 ] {4d608dcb-4a8a-4e53-b61b-7e5c288d67b1} <Error> executeQuery: Code: 395, e.displayText() = DB::Exception: Value passed to 'throwIf' function is non zero (version 19.13.1.1) (from [::1]:41762) (in query: SELECT throwIf(1)), Stack trace:

#0 0x3e98600 StackTrace::StackTrace() /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Common/StackTrace.cpp:208
#1 0x3e98472 DB::Exception::Exception(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Common/Exception.h:27
#2 0x4068f6d DB::FunctionThrowIf::executeImpl(DB::Block&, std::vector<unsigned long, std::allocator<unsigned long> > const&, unsigned long, unsigned long) /opt/milovidov/ClickHouse/build_gcc9/dbms/programs/clickhouse
#3 0x72423e5 DB::PreparedFunctionImpl::defaultImplementationForConstantArguments(DB::Block&, std::vector<unsigned long, std::allocator<unsigned long> > const&, unsigned long, unsigned long, bool) /usr/local/include/c++/9.1.0/bits/stl_vector.h:1043
#4 0x7242871 DB::PreparedFunctionImpl::executeWithoutLowCardinalityColumns(DB::Block&, std::vector<unsigned long, std::allocator<unsigned long> > const&, unsigned long, unsigned long, bool) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Functions/IFunction.cpp:303
#5 0x7243579 DB::PreparedFunctionImpl::execute(DB::Block&, std::vector<unsigned long, std::allocator<unsigned long> > const&, unsigned long, unsigned long, bool) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Functions/IFunction.cpp:464
#6 0x740facb DB::ExpressionAction::prepare(DB::Block&, DB::Settings const&) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/ExpressionActions.cpp:217
#7 0x74102c4 DB::ExpressionActions::addImpl(DB::ExpressionAction, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&) /usr/local/include/c++/9.1.0/bits/stl_vector.h:1186
#8 0x74106a3 DB::ExpressionActions::add(DB::ExpressionAction const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/ExpressionActions.cpp:643
#9 0x7556cc3 DB::ScopeStack::addAction(DB::ExpressionAction const&) /usr/local/include/c++/9.1.0/bits/stl_iterator.h:807
#10 0x755a28c DB::ActionsVisitor::visit(std::shared_ptr<DB::IAST> const&) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/ActionsVisitor.cpp:516
#11 0x755969f DB::ActionsVisitor::visit(std::shared_ptr<DB::IAST> const&) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/ActionsVisitor.cpp:536
#12 0x74220c5 DB::ExpressionAnalyzer::getRootActions(std::shared_ptr<DB::IAST> const&, bool, std::shared_ptr<DB::ExpressionActions>&, bool) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/ActionsVisitor.h:68
#13 0x74245bf DB::ExpressionAnalyzer::appendSelect(DB::ExpressionActionsChain&, bool) /usr/local/include/c++/9.1.0/bits/shared_ptr_base.h:729
#14 0x6d52430 DB::InterpreterSelectQuery::analyzeExpressions(DB::QueryProcessingStage::Enum, bool, std::shared_ptr<DB::FilterInfo> const&) /usr/local/include/c++/9.1.0/bits/stl_vector.h:1005
#15 0x6d6f3e5 void DB::InterpreterSelectQuery::executeImpl<DB::InterpreterSelectQuery::Pipeline>(DB::InterpreterSelectQuery::Pipeline&, std::shared_ptr<DB::IBlockInputStream> const&, bool) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/InterpreterSelectQuery.cpp:810
#16 0x6d53e98 DB::InterpreterSelectQuery::InterpreterSelectQuery(std::shared_ptr<DB::IAST> const&, DB::Context const&, std::shared_ptr<DB::IBlockInputStream> const&, std::shared_ptr<DB::IStorage> const&, DB::SelectQueryOptions const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) /usr/local/include/c++/9.1.0/bits/shared_ptr_base.h:729
#17 0x6d54688 DB::InterpreterSelectQuery::InterpreterSelectQuery(std::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) /usr/local/include/c++/9.1.0/bits/shared_ptr_base.h:729
#18 0x6d73630 DB::InterpreterSelectWithUnionQuery::InterpreterSelectWithUnionQuery(std::shared_ptr<DB::IAST> const&, DB::Context const&, DB::SelectQueryOptions const&, std::vector<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) /usr/local/include/c++/9.1.0/bits/vector.tcc:112
#19 0x6d3847b DB::InterpreterFactory::get(std::shared_ptr<DB::IAST>&, DB::Context&, DB::QueryProcessingStage::Enum) /usr/local/include/c++/9.1.0/bits/stl_vector.h:677
#20 0x6e72a66 DB::executeQueryImpl(char const*, char const*, DB::Context&, bool, DB::QueryProcessingStage::Enum, bool) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/executeQuery.cpp:241
#21 0x6e72c69 DB::executeQuery(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, DB::Context&, bool, DB::QueryProcessingStage::Enum, bool) /home/milovidov/ClickHouse/build_gcc9/../dbms/src/Interpreters/executeQuery.cpp:487
#22 0x3edbf3c DB::TCPHandler::runImpl() /home/milovidov/ClickHouse/build_gcc9/../dbms/programs/server/TCPHandler.cpp:203
#23 0x3edc7ac DB::TCPHandler::run() /home/milovidov/ClickHouse/build_gcc9/../dbms/programs/server/TCPHandler.cpp:1078
#24 0x787e370 Poco::Net::TCPServerConnection::start() /home/milovidov/ClickHouse/build_gcc9/../contrib/poco/Net/src/TCPServerConnection.cpp:57
#25 0x787ea49 Poco::Net::TCPServerDispatcher::run() /usr/local/include/c++/9.1.0/bits/atomic_base.h:327
#26 0x7f63781 Poco::PooledThread::run() /usr/local/include/c++/9.1.0/x86_64-pc-linux-gnu/bits/gthr-default.h:748
#27 0x7f617bc Poco::ThreadImpl::runnableEntry(void*) /home/milovidov/ClickHouse/build_gcc9/../contrib/poco/Foundation/include/Poco/AutoPtr.h:205
#28 0xbcf9290 execute_native_thread_routine /home/milovidov/ClickHouse/ci/workspace/gcc/gcc-build/x86_64-pc-linux-gnu/libstdc++-v3/include/bits/unique_ptr.h:81
#29 0x7fa97718a6db start_thread ?
#30 0x7fa97670988f __clone ?

[kreuzerkrieg]

Looks like just what the doctor ordered!
How about time it takes? Something one can live with that?

[alexey-milovidov]

For non-optimized build:

• first thrown exception: 1.5 sec;
• subsequent exceptions (with different stack traces): 0.75 sec;

For optimized build:

• first thrown exception: 100 ms;
• subsequent exceptions (with different stack traces): 10..20 ms;

[kreuzerkrieg]

you are da man!
but I loved these numbers before the edit :)

[alexey-milovidov]

Available in master.

PS. If you install from packages, don't forget to install clickhouse-common-dbg package that ships debug info.

[kreuzerkrieg]

Thanks!