From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from barracuda.ebox.ca (barracuda.ebox.ca [96.127.255.19]) by sourceware.org (Postfix) with ESMTPS id 4B626388CC0B for ; Wed, 16 Dec 2020 20:47:40 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.3.2 sourceware.org 4B626388CC0B X-ASG-Debug-ID: 1608151658-0c856e6cd54a9e10001-fS2M51 Received: from smtp.ebox.ca (smtp.ebox.ca [96.127.255.82]) by barracuda.ebox.ca with ESMTP id BWUVEZFy3LLtY3Cd (version=TLSv1 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Wed, 16 Dec 2020 15:47:39 -0500 (EST) X-Barracuda-Envelope-From: simon.marchi@efficios.com X-Barracuda-RBL-Trusted-Forwarder: 96.127.255.82 Received: from epycamd.internal.efficios.com (192-222-181-218.qc.cable.ebox.net [192.222.181.218]) by smtp.ebox.ca (Postfix) with ESMTP id DDFF5441D64; Wed, 16 Dec 2020 15:47:38 -0500 (EST) From: Simon Marchi X-Barracuda-RBL-IP: 192.222.181.218 X-Barracuda-Effective-Source-IP: 192-222-181-218.qc.cable.ebox.net[192.222.181.218] X-Barracuda-Apparent-Source-IP: 192.222.181.218 To: gdb-patches@sourceware.org Cc: Simon Marchi Subject: [PATCH v2 1/3] gdb: make "set debug timestamp" work nice with new debug printouts Date: Wed, 16 Dec 2020 15:47:35 -0500 X-ASG-Orig-Subj: [PATCH v2 1/3] gdb: make "set debug timestamp" work nice with new debug printouts Message-Id: <20201216204737.900975-1-simon.marchi@efficios.com> X-Mailer: git-send-email 2.29.2 MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Barracuda-Connect: smtp.ebox.ca[96.127.255.82] X-Barracuda-Start-Time: 1608151659 X-Barracuda-Encrypted: DHE-RSA-AES256-SHA X-Barracuda-URL: https://96.127.255.19:443/cgi-mod/mark.cgi X-Virus-Scanned: by bsmtpd at ebox.ca X-Barracuda-Scan-Msg-Size: 5973 X-Barracuda-BRTS-Status: 1 X-Barracuda-Spam-Score: 0.50 X-Barracuda-Spam-Status: No, SCORE=0.50 using global scores of TAG_LEVEL=1000.0 QUARANTINE_LEVEL=1000.0 KILL_LEVEL=8.0 tests=BSF_RULE7568M X-Barracuda-Spam-Report: Code version 3.2, rules version 3.2.3.86572 Rule breakdown below pts rule name description ---- ---------------------- -------------------------------------------------- 0.50 BSF_RULE7568M Custom Rule 7568M X-Spam-Status: No, score=-22.4 required=5.0 tests=BAYES_00, GIT_PATCH_0, KAM_DMARC_NONE, KAM_DMARC_STATUS, RCVD_IN_DNSWL_LOW, SPF_HELO_NONE, SPF_SOFTFAIL, TXREP autolearn=ham autolearn_force=no version=3.4.2 X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on server2.sourceware.org X-BeenThere: gdb-patches@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Gdb-patches mailing list List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 16 Dec 2020 20:47:41 -0000 New in v2: - implement by modifying vprintf_unfiltered rather than debug_prefixed_vprintf. I tried enabling debug timestamps, and realized that it doesn't play well with the revamp of the debug printouts I've been working on: $ ./gdb -q -nx --data-directory=data-directory -ex "set debug infrun" -ex "set debug timestamp" a.out Reading symbols from a.out... (gdb) start Temporary breakpoint 1 at 0x1131: file test.c, line 2. Starting program: /home/smarchi/build/binutils-gdb-all-targets/gdb/a.out 939897.769338 [infrun] infrun_async: 939897.769383 enable=1 939897.769409 939897.915218 [infrun] proceed: 939897.915281 addr=0x7ffff7fd0100, signal=GDB_SIGNAL_0 939897.915315 939897.915417 [infrun] start_step_over: 939897.915464 stealing global queue of threads to step, length = 0 939897.915502 939897.915567 [infrun] operator(): 939897.915601 step-over queue now empty 939897.915633 939897.915690 [infrun] proceed: 939897.915729 resuming process 636244 939897.915768 939897.915892 [infrun] resume_1: 939897.915954 step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [process 636244] at 0x7ffff7fd0100 939897.915991 939897.916119 [infrun] prepare_to_wait: 939897.916153 prepare_to_wait 939897.916201 939897.916661 [infrun] target_wait (-1.0.0, status) = [infrun] 636244.636244.0 [process 636244], [infrun] status->kind = stopped, signal = GDB_SIGNAL_TRAP 939897.916734 [infrun] handle_inferior_event: 939897.916768 status->kind = stopped, signal = GDB_SIGNAL_TRAP 939897.916799 This is due to debug_prefixed_vprintf being implemented as three separate calls to debug_printf / debug_vprintf. Each call gets its own timestamp and newline, curtesy of vprintf_unfiltered. My first idea was to add a "line_start" parameter to debug_vprintf, allowing the caller to say whether the print is the start of the line. A debug timestamp would only be printed if line_start was true. However, that was much more invasive than the simple fix implemented in this patch. My second idea was to make debug_prefixed_vprintf use string_printf and issue a single call to debug_printf. That would however prevent future use of styling in the debug messages. What is implemented in this patch is the same as is implemented in GDBserver: the timestamp-printing code in GDB tracks whether the last debug output ended with a newline. If so, it prints a timestamp on the next debug output. After the fix, it looks like this: $ ./gdb -q -nx --data-directory=data-directory -ex "set debug infrun" -ex "set debug timestamp" a.out Reading symbols from a.out... (gdb) start Temporary breakpoint 1 at 0x1131: file test.c, line 2. Starting program: /home/smarchi/build/binutils-gdb-all-targets/gdb/a.out 941112.135662 [infrun] infrun_async: enable=1 941112.279930 [infrun] proceed: addr=0x7ffff7fd0100, signal=GDB_SIGNAL_0 941112.280064 [infrun] start_step_over: stealing global queue of threads to step, length = 0 941112.280125 [infrun] operator(): step-over queue now empty 941112.280194 [infrun] proceed: resuming process 646228 941112.280332 [infrun] resume_1: step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [process 646228] at 0x7ffff7fd0100 941112.280480 [infrun] prepare_to_wait: prepare_to_wait 941112.281004 [infrun] target_wait (-1.0.0, status) = [infrun] 646228.646228.0 [process 646228], [infrun] status->kind = stopped, signal = GDB_SIGNAL_TRAP 941112.281078 [infrun] handle_inferior_event: status->kind = stopped, signal = GDB_SIGNAL_TRAP gdb/ChangeLog: * utils.c (vfprintf_unfiltered): Print timestamp only when previous debug output ended with a newline. Change-Id: Idcfe3acc7e3d0f526a5f0a43a5e0884bf93c41ae --- gdb/utils.c | 34 +++++++++++++++++++--------------- 1 file changed, 19 insertions(+), 15 deletions(-) diff --git a/gdb/utils.c b/gdb/utils.c index abcf6e256b0..5d6fa61910c 100644 --- a/gdb/utils.c +++ b/gdb/utils.c @@ -2126,26 +2126,30 @@ vfprintf_unfiltered (struct ui_file *stream, const char *format, va_list args) { if (debug_timestamp && stream == gdb_stdlog) { - using namespace std::chrono; - int len, need_nl; + static bool needs_timestamp = true; + /* Print timestamp if previous print ended with a \n. */ + if (needs_timestamp) + { + using namespace std::chrono; + + steady_clock::time_point now = steady_clock::now (); + seconds s = duration_cast (now.time_since_epoch ()); + microseconds us = duration_cast (now.time_since_epoch () - s); + std::string timestamp = string_printf ("%ld.%06ld ", + (long) s.count (), + (long) us.count ()); + fputs_unfiltered (timestamp.c_str (), stream); + } + + /* Print the message. */ string_file sfile; cli_ui_out (&sfile, 0).vmessage (ui_file_style (), format, args); std::string linebuffer = std::move (sfile.string ()); + fputs_unfiltered (linebuffer.c_str (), stream); - steady_clock::time_point now = steady_clock::now (); - seconds s = duration_cast (now.time_since_epoch ()); - microseconds us = duration_cast (now.time_since_epoch () - s); - - len = linebuffer.size (); - need_nl = (len > 0 && linebuffer[len - 1] != '\n'); - - std::string timestamp = string_printf ("%ld.%06ld %s%s", - (long) s.count (), - (long) us.count (), - linebuffer.c_str (), - need_nl ? "\n": ""); - fputs_unfiltered (timestamp.c_str (), stream); + size_t len = linebuffer.length (); + needs_timestamp = (len > 0 && linebuffer[len - 1] == '\n'); } else vfprintf_maybe_filtered (stream, format, args, false, true); -- 2.29.2