From 2b7b93635ed90c34a7ffeff08b32b04e04f7f7cd Mon Sep 17 00:00:00 2001 From: Fabian Keil Date: Tue, 13 Oct 2015 18:19:42 +0200 Subject: [PATCH 165/257] libdtrace: Replace another timestamp related assert() with a warning It triggered a lot less often, but was still annoying. Example: 2015 Oct 13 18:01:06: v_free_target: 20888, v_free_count: 44001, v_cache_count: 0. 2015 Oct 13 18:01:06: v_inactive_target: 31332. v_inactive_count: 364311. deficit: 0 2015 Oct 13 18:01:06: after-inactive-scan pass 3: page shortage: -23113, inactive page surplus: 10000, addl shortage: 0, vnodes skipped: 0. 2015 Oct 13 18:01:06: before-active-scan pass 3: page_shortage: -356092. 2015 Oct 13 18:01:06: after-active-scan pass 3: page_shortage: -356092. 2015 Oct 13 18:01:06: checked-inactive-pages: Inactive page surplus: 10000, above limit: 252979. dtrace: cpu clocks out of sync (18128465664478 < 18128471798881; offset: 6134403). Results may be incorrect! dtrace: cpu clocks out of sync (18129463671844 < 18129469778266; offset: 6106422). Results may be incorrect! 2015 Oct 13 18:01:07: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253446. 2015 Oct 13 18:01:07: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253446. 2015 Oct 13 18:01:07: before-inactive-scan: Scan goal 1: Move inactive to cache or free. 2015 Oct 13 18:01:07: before-inactive-scan: Page shortage: -37096, inactive page surplus: 10000 2015 Oct 13 18:01:07: v_free_target: 20888, v_free_count: 57984, v_cache_count: 0. 2015 Oct 13 18:01:07: v_inactive_target: 31332. v_inactive_count: 364778. deficit: 0 2015 Oct 13 18:01:07: after-inactive-scan pass 1: page shortage: -37203, inactive page surplus: 9893, addl shortage: 0, vnodes skipped: 0. 2015 Oct 13 18:01:07: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253250. 2015 Oct 13 18:01:07: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253250. 2015 Oct 13 18:01:07: before-inactive-scan: Scan goal 2: Launder dirty pages. 2015 Oct 13 18:01:07: before-inactive-scan: Page shortage: -37191, inactive page surplus: 10000 2015 Oct 13 18:01:07: v_free_target: 20888, v_free_count: 58079, v_cache_count: 0. 2015 Oct 13 18:01:07: v_inactive_target: 31332. v_inactive_count: 364582. deficit: 0 2015 Oct 13 18:01:07: after-inactive-scan pass 2: page shortage: -37194, inactive page surplus: 9997, addl shortage: 0, vnodes skipped: 0. 2015 Oct 13 18:01:07: before-active-scan pass 2: page_shortage: -370441. 2015 Oct 13 18:01:07: after-active-scan pass 2: page_shortage: -370441. 2015 Oct 13 18:01:07: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253268. dtrace: cpu clocks out of sync (18130462652022 < 18130468761237; offset: 6109215). Results may be incorrect! 2015 Oct 13 18:01:08: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253331. 2015 Oct 13 18:01:08: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253331. 2015 Oct 13 18:01:08: before-inactive-scan: Scan goal 1: Move inactive to cache or free. 2015 Oct 13 18:01:08: before-inactive-scan: Page shortage: -34625, inactive page surplus: 10000 2015 Oct 13 18:01:08: v_free_target: 20888, v_free_count: 55513, v_cache_count: 0. 2015 Oct 13 18:01:08: v_inactive_target: 31332. v_inactive_count: 364663. deficit: 0 2015 Oct 13 18:01:08: after-inactive-scan pass 1: page shortage: -34645, inactive page surplus: 9980, addl shortage: 0, vnodes skipped: 0. 2015 Oct 13 18:01:08: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253286. 2015 Oct 13 18:01:08: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253286. 2015 Oct 13 18:01:08: before-inactive-scan: Scan goal 2: Launder dirty pages. 2015 Oct 13 18:01:08: before-inactive-scan: Page shortage: -34395, inactive page surplus: 10000 2015 Oct 13 18:01:08: v_free_target: 20888, v_free_count: 55283, v_cache_count: 0. 2015 Oct 13 18:01:08: v_inactive_target: 31332. v_inactive_count: 364618. deficit: 0 2015 Oct 13 18:01:08: after-inactive-scan pass 2: page shortage: -34396, inactive page surplus: 9999, addl shortage: 0, vnodes skipped: 0. 2015 Oct 13 18:01:08: before-active-scan pass 2: page_shortage: -367391. 2015 Oct 13 18:01:08: after-active-scan pass 2: page_shortage: -367391. 2015 Oct 13 18:01:08: checked-inactive-pages: Inactive page surplus: 10000, above limit: 253285. 2015 Oct 13 18:01:09: checked-inactive-pages: Inactive page surplus: 10000, above limit: 256158. 2015 Oct 13 18:01:09: before-inactive-scan: Scan goal 3: Pageout dirty pages. 2015 Oct 13 18:01:09: before-inactive-scan: Page shortage: -34665, inactive page surplus: 10000 2015 Oct 13 18:01:09: v_free_target: 20888, v_free_count: 55553, v_cache_count: 0. 2015 Oct 13 18:01:09: v_inactive_target: 31332. v_inactive_count: 367490. deficit: 0 dtrace: cpu clocks out of sync (18131462608939 < 18131468746340; offset: 6137401). Results may be incorrect! Assertion failed: (timestamp >= dtp->dt_last_timestamp), file /usr/src/cddl/lib/libdtrace/../../../cddl/contrib/opensolaris/lib/libdtrace/common/dt_consume.c, line 3352. Obtained from: ElectroBSD --- cddl/contrib/opensolaris/lib/libdtrace/common/dt_consume.c | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/cddl/contrib/opensolaris/lib/libdtrace/common/dt_consume.c b/cddl/contrib/opensolaris/lib/libdtrace/common/dt_consume.c index 39530cf41e83..3b66c3522cdc 100644 --- a/cddl/contrib/opensolaris/lib/libdtrace/common/dt_consume.c +++ b/cddl/contrib/opensolaris/lib/libdtrace/common/dt_consume.c @@ -3349,7 +3349,13 @@ dtrace_consume(dtrace_hdl_t *dtp, FILE *fp, break; timestamp = dt_buf_oldest(buf, dtp); - assert(timestamp >= dtp->dt_last_timestamp); + if (timestamp < dtp->dt_last_timestamp) { + warnx("cpu clocks out of sync " + "(%ju < %ju; offset: %ju). " + "Results may be incorrect!", + timestamp, dtp->dt_last_timestamp, + dtp->dt_last_timestamp - timestamp); + } dtp->dt_last_timestamp = timestamp; if (timestamp == buf->dtbd_timestamp) { -- 2.11.0