feat(logs): batching #1338
feat(logs): batching #1338
Conversation
# Conflicts: # examples/example.c
Current IssuesNon-IssuesDropping Logs
The time-to-flush seems higher than local testing (from an average of 600us to 1200us) which could explain the high number of dropped logs. In the 5/50 example below, we even have flushes taking 76000us, which definitely blocks the logs buffer long enough to drop 90% of incoming logs. Example runs: Potential SolutionWe can only handle 20k logs/s project-wide, before abuse quota hits. This equates to one log every 50us; our stress-test might therefore be stressing the system too much (source: internal notion page) FixedStuck flushing (Windows)In some runs we seemingly get stuck trying to flush logs. We see a trigger every 5s, even though the timer_task should have stopped SolutionWe had a leftover sleep in the code that was removed in 208952b ; this caused the Windows tests to run for 30 minutes before closing Threaded logs test getting stuck (Windows)Different from the Fixed Logs Flushing problem mentioned below, we noticed that on 32-bit Windows the threaded logs test gets 'stuck'. See an example run here. In the logs we can notice the following; an unexpected return on the logs flush trigger followed by a failed assert in sentry_value.c. SolutionFixed in #1362 , we had some overlooked ownership issues with collecting the attributes for the logs, which caused Windows to show an error window (causing the test to hang). This was not a Windows-specific issue, but CI luckily (accidentally) caught it. |
- too much variability in thread scheduling, so we can expect pretty much anything
|
The switch statement on the return value of Currently it expects: |
* add `before_send_log` callback * add `before_send_log` callback tests * (temporary) add debug for calling sentry_options_free * remove early return * add late return * cleanup
* let the producer thread sleep for 1ms between logs * fix two missing NULL checks in the json serializer * clean up logging and early exits in `enqueue_log_single()` * clean up ownerships in logs * eliminate clones (we expect that everything outlives the logs being sent except local construction) * use incref everywhere where we ref global state. this was the cause of the UAF, partially solved with the clones but a few were missing. no reason to clone if we do not want to disconnect for a particular object graph * clarify that add_attribute expects ownership * minimize scope_mut by moving os_context out * raise that log output in throughput tests add to variability (stdout logging should be turned off when running a limit) * log error in case we weren't able to start the log batching worker * fix clang-cl warning * ci: fix failing mingw build (#1361) * ci: fix failing mingw build * split `ASM_MASM_COMPILER` and `_FLAGS` * add `ASM_MASM_FLAGS` in `mingw` install step * specify the `CMAKE_ASM_MASM_COMPILER` as a `FILEPATH` * clean up CMAKE_DEFINES construction so it is easier to diff in the future * fix `LLVM_MINGW_INSTALL_PATH` to be referenced locally rather than $env (cherry picked from commit 519554f) * use UNREACHABLE macro to fix anal warnings
|
* first attempt at double buffered * remove the sleep from the windows thread func * clean up thread waiting in the example * adapt the double buffer to use retries, fix remaining issues, clean up and write inline docs * return early in example on sentry_init error. * fix formatting via shorter name for thread gate atomic * improve inline docs of log_buffer_t members * fetch os_context from scope * move scope/options data retrieval into separate function + add expected keys to test * update logs API to return status code * cleanup * add log-event trace connection test * remove duplicate test * specify macOS SDKROOT --------- Co-authored-by: JoshuaMoelans <[email protected]>
* add sentry logs option * add sentry logs option to example * feat(logs): add sentry log API + send first logs (#1272) * add sentry log API + send first logs * fix log_level_as_string * attach attributes to logs * attach formatted message + args * add to example * add more attributes * cleanup * windows warning-as-error * windows warning-as-error v2 * windows warning-as-error v2 (final) * add unit tests for initial logs * memleak attempted fix * memleak attempted fix 2 * cleanup * use `sentry_level_t` instead of new log level enum * add SENTRY_LEVEL_TRACE to sentry_logger * quick anti-brownout fix - see #1274 * fix missing SENTRY_LEVEL_INFO string return * fix logger level check + add test * cleanup logs parameter extraction * warn-as-error fix * const char* fix * static function * feat(logs): add (u)int64 sentry_value_t type (#1301) * add (u)int64 sentry_value_t type * add value_to_msgpack missing switch cases * remove undefined behavior test (C99 6.3.1.4) * avoid Windows sized integer name collision * cleanup & apply code review feedback * more cleanup & remove type coercion * update logs param conversion * own uint64 string * apply suggestions from code review * fixed log parameter conversion * update example to avoid warning-as-error * feat(logs): batching (#1338) * initial queue attempt * add timer * prototype double buffer approach * update logs unit tests for batching * replace timer with bgworker * add first integration tests * update example.c with correct log thread amounts * cleanup * add wait for 'adding' logs in flush logic * go back to single queue for performance testing * add time checks * add ToDos + cleanup sentry_value_t cloning * initial attempt * cond_wait for timer + 'adding' spinlock * add sleep for tests * add sleep for tests * force flush before attempting timer_worker shutdown * add proper cond_wait for 'adding' counter * revert to manual flush on shutdown instead of timer thread flush * add separate timer_stop atomic * cleanup + replace 'adding' cond_wait by pure spinlock * change bgworker for simpler thread implementation * cleanup * fix memleak * fixes * cleanup * cleanup * windows fixes * update shutdown order * fixes * explicit check to stop timer task * windows cleanup * loosen threaded test assertion for CI - too much variability in thread scheduling, so we can expect pretty much anything * add continue for unexpected logs flush trigger instead of attempting flush * Windows re-add condition variable trigger case * feat(logs): add `before_send_log` (#1355) * add `before_send_log` callback * add `before_send_log` callback tests * (temporary) add debug for calling sentry_options_free * remove early return * add late return * cleanup * fix ownership issues in single buffer batching (#1362) * let the producer thread sleep for 1ms between logs * fix two missing NULL checks in the json serializer * clean up logging and early exits in `enqueue_log_single()` * clean up ownerships in logs * eliminate clones (we expect that everything outlives the logs being sent except local construction) * use incref everywhere where we ref global state. this was the cause of the UAF, partially solved with the clones but a few were missing. no reason to clone if we do not want to disconnect for a particular object graph * clarify that add_attribute expects ownership * minimize scope_mut by moving os_context out * raise that log output in throughput tests add to variability (stdout logging should be turned off when running a limit) * log error in case we weren't able to start the log batching worker * fix clang-cl warning * ci: fix failing mingw build (#1361) * ci: fix failing mingw build * split `ASM_MASM_COMPILER` and `_FLAGS` * add `ASM_MASM_FLAGS` in `mingw` install step * specify the `CMAKE_ASM_MASM_COMPILER` as a `FILEPATH` * clean up CMAKE_DEFINES construction so it is easier to diff in the future * fix `LLVM_MINGW_INSTALL_PATH` to be referenced locally rather than $env (cherry picked from commit 519554f) * use UNREACHABLE macro to fix anal warnings * batching double buffered (#1365) * first attempt at double buffered * remove the sleep from the windows thread func * clean up thread waiting in the example * adapt the double buffer to use retries, fix remaining issues, clean up and write inline docs * return early in example on sentry_init error. * fix formatting via shorter name for thread gate atomic * improve inline docs of log_buffer_t members * fetch os_context from scope * move scope/options data retrieval into separate function + add expected keys to test * update logs API to return status code * cleanup * add log-event trace connection test * remove duplicate test * specify macOS SDKROOT --------- Co-authored-by: JoshuaMoelans <[email protected]> * add flush retry for missed flush requests * move flush retry into flush function * add docs --------- Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * update CHANGELOG.md * use `trace_id` from scoped spans for logs * fix copy-paste leftover + docs * add log_sleep for thread test + variable NUM_LOGS * no `usleep` on windows :( * fix seconds->milliseconds * cleanup * test(logs): add 32-bit vargs test (#1370) * add vargs conversion test * add ifdef for 32-bit systems * Update tests/unit/test_logs.c Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * add comment * fix comment --------- Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * Apply suggestions from code review Co-authored-by: Mischan Toosarani-Hausberger <[email protected]> * post-merge cleanup * pin ruamel version * let's unpin ruamel.yaml.clib to get 0.2.14 which seemingly fixes the missing header: https://sourceforge.net/p/ruamel-yaml-clib/tickets/47/#de77 * add empty payload check * log output of logger tests if we fail to find the pre-crash marker * fix: move `is_tsan` marker into the `has_crashpad` condition... ...so we can ignore in which module a `crashpad` test runs. * fix: update `has_crashpad` condition comment * really only move `is_tsan`, but keep the module level `pytestmark` * CHANGELOG.md update * CHANGELOG.md update * CHANGELOG.md update --------- Co-authored-by: Mischan Toosarani-Hausberger <[email protected]>
Implements a double buffer queue for logs batching.
#skip-changelog