Commit Graph

203 Commits

Author SHA1 Message Date
Dan Adkins 07c4924645 Fix typo in format string. 2023-02-08 17:15:07 -08:00
Dan Adkins f36c20248e Add timer_monotonic() to CommitDebug trace events.
CommitDebug trace events are useful for measuring, in detail, the time spent in
the various parts of a single transaction. Like all log events, they have a time
associated with them. This time comes for now(), which in a real fdb system is
only updated in the run loop. This renders the timestamps inaccurate in certain
CPU bound sections which don't have a wait, e.g. in the resolver.

The desired solution is to directly call ::timer_monotonic() instead of now()
for a timestamp, since ::timer_monotonic() is what now() ultimately uses in
the run loop, but is updated between waits as well.

In order to not disrupt any current uses of the logs which might depend on the
current behavior of the Time field, we introduced the `MonotonicTime` field.

This change only affects CommitDebug trace events, not trace events in general.
2023-02-08 13:39:56 -08:00
Dan Adkins be70a341f2 Revert "Use real clock source for trace events in real fdbserver, but now() in simulation. (#9270)"
This reverts commit 02f78500b5.

That changed the default behavior of the clock used for trace logs, which
might break some tooling or workflows.
2023-02-02 10:30:31 -08:00
Dan Adkins 02f78500b5
Use real clock source for trace events in real fdbserver, but now() in simulation. (#9270)
CommitDebug trace events are useful for measuring, in detail, the time spent in
the various parts of a single transaction. Like all log events, they have a time
associated with them. This time comes for now(), which in a real fdb system is
only updated in the run loop. This renders the timestamps inaccurate in certain
CPU bound sections which don't have a wait, e.g. in the resolver.

We want to preserve the current behavior in simulation, where the timestamps are
artificial, deterministic between runs, and only updated in the run loop.

In a real system, we prefer to use a real clock so we can use the difference
between two trace events in the logs as a measurement of elapsed time.

This does not modify the behavior of other parts of the system, which use the
cached now() for various purposes.
2023-02-02 12:33:45 -05:00
Vaidas Gasiunas f8b1da8bc6
An option to initialize client tracing in setupNetwork (#9209)
* client_config_tester: use a generic mechanism to set specific network options

* trace_initialize_on_setup option to initialize client traces on network setup without local IP address

* trace_initialize_on_setup: Addressing review comments

* Restore correct formatting

* trace_initialize_on_setup: Update go bindings

* Include PID for identification into trace file names by default

* Use the same naming pattern for trace files in all configurations

* Empty commit
2023-02-02 10:00:51 +01:00
Dennis Zhou 8ed149728f trace: add tryGet variants for numeric types 2022-12-06 11:57:26 -08:00
Vaidas Gasiunas 18b852c4e4
Improving troubleshooting of stopping the FDB client thread (#8629)
* Upgrade tests: dump thread call stacks of the tester process if it fails to terminate

* ApiTester: log before and after stopping the network thread

* Catch and print exceptions in closeTraceFile; Close trace file at the end of MVC runNetwork

* Change trace event name for MVC runNetwork termination

Co-authored-by: A.J. Beamon <aj.beamon@snowflake.com>

Co-authored-by: A.J. Beamon <aj.beamon@snowflake.com>
2022-11-03 13:20:21 +01:00
A.J. Beamon 4fd64630e8 Convert literal string ref instances to use _sr suffix 2022-09-19 11:35:58 -07:00
sfc-gh-tclinkenbeard 82adc1e856 Make g_simulator a pointer 2022-09-15 09:00:33 -07:00
Chaoguang Lin 06aa6ee5ff
Add system monitor for flowprocess (#6925)
* Update network address in trace logs; Add system monitor for flowprocess

* Create a new trace file with the correct process address for flowprocess

* Remove unused debugging traces

* Add a new error lock_file_failure; Change please_reboot_remote_kv_store to please_reboot_kv_store; Add the code to only reboot the kv store but not the worker; Remove some unnecessay traces

* Add error handling for file_not_found in handleIOErrors

* Format worker.actor.cpp file
2022-08-24 00:40:38 -07:00
Marian Dvorsky 3a53ec3115
Call getTraceThreadId() before we enable allocation tracing (#7888) 2022-08-23 20:25:08 +02:00
Xiaoxi Wang c199ea054c format code 2022-08-06 20:01:35 -07:00
Xiaoxi Wang 90b0d74875 DebugRelocationTraceEvent; TraceInterval randomId: 2022-08-04 15:28:33 -07:00
Lukas Joswiak 88557d9169 Simplify function call when transaction is null 2022-06-22 14:50:17 -07:00
Andrew Noyes 0fea3fb731
Save a bunch of copies in the trace thread (#7392)
Currently, a std::string is copied unnecessarily for every key and value
in a trace event.

This actually showed up in a jemalloc heap profile while I was
investigating something unrelated. I was surprised to see it since these
allocations should have a very short lifetime.
2022-06-15 12:29:15 -07:00
Vaidas Gasiunas 4d6ec7663f Close file at the end of runNetwork rather than in stopNetwork in order to avoid a race condition,
also in order to continue tracing the pending network thread activity.
Poll event throttler only in the network thread in order to avoid a race condition.
2022-05-31 13:59:09 +02:00
Markus Pilman 85757eb47c
Update flow/Trace.cpp 2022-04-20 15:30:42 -06:00
Markus Pilman f7a8ebf818
Update flow/Trace.cpp
Co-authored-by: A.J. Beamon <aj.beamon@snowflake.com>
2022-04-20 11:55:01 -06:00
Markus Pilman d4ee7be1d7 Reduce excessive tracing and fail after 1M traces 2022-04-19 21:11:51 -06:00
sfc-gh-tclinkenbeard a71099471b Update copyright header dates 2022-03-21 13:36:23 -07:00
A.J. Beamon d45bae11b7 Fix substring call when reporting details about a trace event that was longer than the legal limit. 2022-03-04 13:59:49 -08:00
A.J. Beamon f6b24cd644 Add some extra print debugging if we overflow the trace buffer. 2022-03-01 09:04:15 -08:00
A.J. Beamon 250a88e682 Enforce that trace event suppression calls happen first when using trace event call chaining. Fix various instances where we weren't following this requirement. 2022-02-24 12:25:52 -08:00
Xiaoxi Wang 6dc5921575
createdTime based storage wiggler (#6219)
* add storagemetadata

* add StorageWiggler;

* fix serverMetadataKey bug

* add metadata tracker in storage tracker

* finish StorageWiggler

* update next storage ID

* change pid to server id

* write metadata when seed SS

* add status json fields

* remove pid based ppw iteration

* fix time expression

* fix tss metadata nonexistence; fix transaction retry when retrieving metadata

* fix checkMetadata bug when store type is wrong

* fix remove storage status json

* format code

* refactor updateNextWigglingStoragePID

* seperate storage metadata tracker and store type tracker

* rename pid

* wiggler stats

* fix completion between waitServerListChange and storageRecruiter

* solve review comments

* rename system key

* fix database lock timeout by adding lock_aware

* format code

* status json

* resolve code format/naming comments

* delete expireNow; change PerpetualStorageWiggleID's value to KeyBackedObjectMap<UID, StorageWiggleValue>

* fix omit start rount

* format code

* status json reset

* solve status json format

* improve status json latency; replace binarywriter/reader to objectwriter/reader; refactor storagewigglerstats transactions

* status timestamp
2022-02-04 15:04:30 -08:00
A.J. Beamon b9581fb768 Convert variable to const& 2022-01-04 09:16:26 -08:00
A.J. Beamon af931ad989 Add support for universal trace fields that apply to all events in a process. Add a universal field on clients called ClientDescription that identifies the client logging the event. 2021-12-10 15:03:14 -08:00
A.J. Beamon b8bd89f88d Shorten the name of external client threads. Add a thread name for trace logging threads. 2021-11-29 09:57:10 -08:00
A.J. Beamon 77c3122391 Slight modification to comment to remove the indication that we flush the trace log explicitly. 2021-09-27 13:17:00 -07:00
A.J. Beamon 0fc3cf44dc When we have a large trace log buffer in simulation, that suggests we may be stuck in a loop that prevents us from running the trace flush. Detect when this has happened and fail the test early, which allows us to do the flush and have logging for the offending loop. 2021-09-27 13:17:00 -07:00
FDB Formatster 2c788c233d apply clang-format to *.c, *.cpp, *.h, *.hpp files 2021-08-27 17:07:47 -07:00
Andrew Noyes 7706b47085 Fix another TSAN warning
```
  Read of size 1 at 0x7f02082ac578 by main thread:
    #0 TraceLog::close() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:487:7 (libfdb_c.so+0xf4928c)
    #1 closeTraceFile() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:759:13 (libfdb_c.so+0xf3992a)
    #2 stopNetwork() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/fdbclient/NativeAPI.actor.cpp:2052:2 (libfdb_c.so+0x58315c)
    #3 ThreadSafeApi::stopNetwork() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../fdbclient/ThreadSafeTransaction.cpp:466:2 (libfdb_c.so+0xce8ad3)
    #4 MultiVersionApi::stopNetwork() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/fdbclient/MultiVersionTransaction.actor.cpp:1756:20 (libfdb_c.so+0x4f7da3)
    #5 fdb_stop_network /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../bindings/c/fdb_c.cpp:134:2 (libfdb_c.so+0x4c84e5)
    #6 main /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../bindings/c/test/unit/trace_partial_file_suffix_test.cpp:93:12 (trace_partial_file_suffix_test+0x40b3d0)

  Previous write of size 1 at 0x7f02082ac578 by thread T1 (mutexes: write M100):
    #0 TraceLog::open(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, unsigned long, unsigned long, Optional<NetworkAddress>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:344:10 (libfdb_c.so+0xf48aaa)
    #1 openTraceFile(NetworkAddress const&, unsigned long, unsigned long, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:741:13 (libfdb_c.so+0xf3828c)
    #2 Database::createDatabase(Reference<ClusterConnectionFile>, int, IsInternal, LocalityData const&, DatabaseContext*) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/fdbclient/NativeAPI.actor.cpp:1695:4 (libfdb_c.so+0x57d57e)
    #3 ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7::operator()() const /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../fdbclient/ThreadSafeTransaction.cpp:124:8 (libfdb_c.so+0xcf018c)
    #4 internal_thread_helper::DoOnMainThreadVoidActorState<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7, internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7> >::a_body1cont1(Void const&, int) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/flow/ThreadHelper.actor.h:45:4 (libfdb_c.so+0xcf018c)
    #5 internal_thread_helper::DoOnMainThreadVoidActorState<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7, internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7> >::a_body1when1(Void const&, int) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/flow/ThreadHelper.actor.g.h:148:15 (libfdb_c.so+0xcf018c)
    #6 internal_thread_helper::DoOnMainThreadVoidActorState<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7, internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7> >::a_callback_fire(ActorCallback<internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7>, 0, Void>*, Void const&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/flow/ThreadHelper.actor.g.h:169:4 (libfdb_c.so+0xcefdef)
    #7 ActorCallback<internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7>, 0, Void>::fire(Void const&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/flow.h:1074:78 (libfdb_c.so+0xcefdef)
    #8 void SAV<Void>::send<Void>(Void&&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/flow.h:462:23 (libfdb_c.so+0x4dd542)
    #9 void Promise<Void>::send<Void>(Void&&) const /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/flow.h:699:8
    ```
2021-08-09 14:06:38 -07:00
Andrew Noyes 39eff8c569 Add trace_partial_file_suffix network option 2021-08-03 09:43:42 -07:00
sfc-gh-tclinkenbeard c74047c665 Merge remote-tracking branch 'origin/master' into fix-more-clang-warnings 2021-07-28 11:51:02 -07:00
Steve Atherton 507c1f11e3 Add .log() to bare TraceEvent() invocations without any .detail()s to avoid clang-tidy warning about immediate destruction of object without use. 2021-07-26 19:55:10 -07:00
sfc-gh-tclinkenbeard b20e02ca25 Fix more -Wreorder-ctor warnings across several files 2021-07-24 11:43:19 -07:00
sfc-gh-tclinkenbeard 3442ebd3b7 Fix more -Wreorder-ctor warnings across many files 2021-07-24 11:20:51 -07:00
Russell Sears 18cde28d6e Add a ThreadID field to each TraceEvent. This is needed for multithreaded client debugging, and should also be helpful for multithreaded storage engines, SSL handshake threadpools, and so on 2021-06-30 14:31:53 -07:00
sfc-gh-tclinkenbeard 399c2c96f0 Remove unnecessary std::string copies from flow 2021-06-09 11:40:01 -07:00
sfc-gh-tclinkenbeard 2bcfbd6816 Move TraceEvent::setErrorKind implementation to cpp file 2021-05-03 11:10:43 -07:00
sfc-gh-tclinkenbeard 13a6c4cf06 Add ErrorKind field to SevError trace events 2021-05-03 11:10:38 -07:00
FDB Formatster df90cc89de apply clang-format to *.c, *.cpp, *.h, *.hpp files 2021-03-10 10:18:07 -08:00
Markus Pilman 2d84e5e1f1
Merge pull request #4254 from sfc-gh-tclinkenbeard/capture-forked-process-output
Capture forked process output in traces
2021-02-24 14:34:24 -07:00
Steve Atherton 76a4293d1d Merge branch 'release-6.3'
# Conflicts:
#	fdbserver/fdbserver.actor.cpp
2021-02-15 02:13:06 -08:00
Steve Atherton f4c9b88908 Merge branch 'release-6.2' into release-6.3
# Conflicts:
#	cmake/CompileBoost.cmake
#	fdbserver/DataDistribution.actor.cpp
#	fdbserver/fdbserver.actor.cpp
#	flow/Error.cpp
2021-02-15 02:05:03 -08:00
Andrew Noyes 4e184fe236 Fix memory errors 2021-02-11 02:58:21 +00:00
sfc-gh-tclinkenbeard acac02587d Trace output from forked processes 2021-01-29 01:31:26 -08:00
sfc-gh-tclinkenbeard 5059228e9e Use unique_ptr for TraceEvent::tmpEventMetric 2020-12-08 09:09:32 -08:00
Andrew Noyes 7fbc4d7391 Resolve conflicts 2020-12-04 23:58:42 +00:00
Andrew Noyes 877997632d Merge branch 'release-6.3' into anoyes/merge-release-6.3-master
Include conflict markers for review purposes
2020-12-04 01:38:07 +00:00
Andrew Noyes dc2bac5670 Resolve conflicts 2020-11-24 19:09:42 +00:00