From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from simark.ca by simark.ca with LMTP id eabkLapm4l+VAQAAWB0awg (envelope-from ) for ; Tue, 22 Dec 2020 16:35:38 -0500 Received: by simark.ca (Postfix, from userid 112) id AF13A1F0AA; Tue, 22 Dec 2020 16:35:38 -0500 (EST) X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on simark.ca X-Spam-Level: X-Spam-Status: No, score=-1.1 required=5.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,MAILING_LIST_MULTI,URIBL_BLOCKED autolearn=ham autolearn_force=no version=3.4.2 Received: from sourceware.org (server2.sourceware.org [8.43.85.97]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by simark.ca (Postfix) with ESMTPS id 64E1C1E552 for ; Tue, 22 Dec 2020 16:35:37 -0500 (EST) Received: from server2.sourceware.org (localhost [IPv6:::1]) by sourceware.org (Postfix) with ESMTP id 6CD513836C57; Tue, 22 Dec 2020 21:35:36 +0000 (GMT) DKIM-Filter: OpenDKIM Filter v2.11.0 sourceware.org 6CD513836C57 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=sourceware.org; s=default; t=1608672936; bh=JBeSZgmZJu+A9BivdCSG90WX4Zq4jbdszdG6h5bR4OE=; h=Subject:To:References:Date:In-Reply-To:List-Id:List-Unsubscribe: List-Archive:List-Post:List-Help:List-Subscribe:From:Reply-To: From; b=dZZ3pVP3cMT1BA1B/VQiJXmYVvF1oMZRt0fOOPt2OqPhBs4T9HNypXMrdRiNY9V1c Oc63Jkzb7FeVJd9pTeloV8Vx4OJyByVUOGEjfy3LDACpgETzdY55qEgDT6QjruzN+y 5/vgphMLHFXMWZgFS28nw8fBxtb/b2If7c2DX7iM= Received: from smtp.polymtl.ca (smtp.polymtl.ca [132.207.4.11]) by sourceware.org (Postfix) with ESMTPS id AF8A6387084D for ; Tue, 22 Dec 2020 21:35:32 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.3.2 sourceware.org AF8A6387084D Received: from simark.ca (simark.ca [158.69.221.121]) (authenticated bits=0) by smtp.polymtl.ca (8.14.7/8.14.7) with ESMTP id 0BMLZQhN013798 (version=TLSv1/SSLv3 cipher=ECDHE-RSA-AES256-GCM-SHA384 bits=256 verify=NOT); Tue, 22 Dec 2020 16:35:31 -0500 DKIM-Filter: OpenDKIM Filter v2.11.0 smtp.polymtl.ca 0BMLZQhN013798 Received: from [10.0.0.213] (192-222-157-6.qc.cable.ebox.net [192.222.157.6]) (using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256) (No client certificate requested) by simark.ca (Postfix) with ESMTPSA id 3967B1E552; Tue, 22 Dec 2020 16:35:26 -0500 (EST) Subject: Re: [PATCH v2 3/3] gdb: introduce scoped debug prints To: Simon Marchi , gdb-patches@sourceware.org References: <20201216204737.900975-1-simon.marchi@efficios.com> <20201216204737.900975-3-simon.marchi@efficios.com> Message-ID: Date: Tue, 22 Dec 2020 16:35:25 -0500 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101 Thunderbird/78.6.0 MIME-Version: 1.0 In-Reply-To: <20201216204737.900975-3-simon.marchi@efficios.com> Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 7bit X-Poly-FromMTA: (simark.ca [158.69.221.121]) at Tue, 22 Dec 2020 21:35:26 +0000 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: , From: Simon Marchi via Gdb-patches Reply-To: Simon Marchi Errors-To: gdb-patches-bounces@sourceware.org Sender: "Gdb-patches" On 2020-12-16 3:47 p.m., Simon Marchi via Gdb-patches wrote: > New in v2: > > - Print indentation using %*s format specifier. > - Add missing space > - Use DISABLE_COPY_AND_ASSIGN > > I spent a lot of time reading infrun debug logs recently, and I think > they could be made much more readable by being indented, to clearly see > what operation is done as part of what other operation. In the current > format, there are no visual cues to tell where things start and end, > it's just a big flat list. It's also difficult to understand what > caused a given operation (e.g. a call to resume_1) to be done. > > To help with this, I propose to add the new scoped_debug_start_end > structure, along with a bunch of macros to make it convenient to use. > > The idea of scoped_debug_start_end is simply to print a start and end > message at construction and destruction. It also increments/decrements > a depth counter in order to make debug statements printed during this > range use some indentation. Some care is taken to handle the fact that > debug can be turned on or off in the middle of such a range. For > example, a "set debug foo 1" command in a breakpoint command, or a > superior GDB manually changing the debug_foo variable. > > Two macros are added in gdbsupport/common-debug.h, which are helpers to > define module-specific macros: > > - scoped_debug_start_end: takes a message that is printed both at > construction / destruction, with "start: " and "end: " prefixes. > - scoped_debug_enter_exit: prints hard-coded "enter" and "exit" > messages, to denote the entry and exit of a function. > > I added some examples in the infrun module to give an idea of how it can > be used and what the result looks like. The macros are in capital > letters (INFRUN_SCOPED_DEBUG_START_END and > INFRUN_SCOPED_DEBUG_ENTER_EXIT) to mimic the existing SCOPE_EXIT, but > that can be changed if you prefer something else. > > Here's an excerpt of the debug > statements printed when doing "continue", where a displaced step is > started: > > [infrun] proceed: enter > [infrun] proceed: addr=0xffffffffffffffff, signal=GDB_SIGNAL_DEFAULT > [infrun] global_thread_step_over_chain_enqueue: enqueueing thread Thread 0x7ffff75a5640 (LWP 2289301) in global step over chain > [infrun] start_step_over: enter > [infrun] start_step_over: stealing global queue of threads to step, length = 1 > [infrun] start_step_over: resuming [Thread 0x7ffff75a5640 (LWP 2289301)] for step-over > [infrun] resume_1: step=1, signal=GDB_SIGNAL_0, trap_expected=1, current thread [Thread 0x7ffff75a5640 (LWP 2289301)] at 0x5555555551bd > [displaced] displaced_step_prepare_throw: displaced-stepping Thread 0x7ffff75a5640 (LWP 2289301) now > [displaced] prepare: selected buffer at 0x5555555550c2 > [displaced] prepare: saved 0x5555555550c2: 1e fa 31 ed 49 89 d1 5e 48 89 e2 48 83 e4 f0 50 > [displaced] amd64_displaced_step_copy_insn: copy 0x5555555551bd->0x5555555550c2: c7 45 fc 00 00 00 00 eb 13 8b 05 d4 2e 00 00 83 > [displaced] displaced_step_prepare_throw: prepared successfully thread=Thread 0x7ffff75a5640 (LWP 2289301), original_pc=0x5555555551bd, displaced_pc=0x5555555550c2 > [displaced] resume_1: run 0x5555555550c2: c7 45 fc 00 > [infrun] infrun_async: enable=1 > [infrun] prepare_to_wait: prepare_to_wait > [infrun] start_step_over: [Thread 0x7ffff75a5640 (LWP 2289301)] was resumed. > [infrun] operator(): step-over queue now empty > [infrun] start_step_over: exit > [infrun] proceed: start: resuming threads, all-stop-on-top-of-non-stop > [infrun] proceed: resuming Thread 0x7ffff7da7740 (LWP 2289296) > [infrun] resume_1: step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [Thread 0x7ffff7da7740 (LWP 2289296)] at 0x7ffff7f7d9b7 > [infrun] prepare_to_wait: prepare_to_wait > [infrun] proceed: resuming Thread 0x7ffff7da6640 (LWP 2289300) > [infrun] resume_1: thread Thread 0x7ffff7da6640 (LWP 2289300) has pending wait status status->kind = stopped, signal = GDB_SIGNAL_TRAP (currently_stepping=0). > [infrun] prepare_to_wait: prepare_to_wait > [infrun] proceed: [Thread 0x7ffff75a5640 (LWP 2289301)] resumed > [infrun] proceed: resuming Thread 0x7ffff6da4640 (LWP 2289302) > [infrun] resume_1: thread Thread 0x7ffff6da4640 (LWP 2289302) has pending wait status status->kind = stopped, signal = GDB_SIGNAL_TRAP (currently_stepping=0). > [infrun] prepare_to_wait: prepare_to_wait > [infrun] proceed: end: resuming threads, all-stop-on-top-of-non-stop > [infrun] proceed: exit > > We can easily see where the call to `proceed` starts and end. We can > also see why there are a bunch of resume_1 calls, it's because we are > resuming threads, emulating all-stop on top of a non-stop target. > > We also see that debug statements nest well with other modules that have > been migrated to use the "new" debug statement helpers (because they all > use debug_prefixed_vprintf in the end. I think this is desirable, for > example we could see the debug statements about reading the DWARF info > of a library nested under the debug statements about loading that > library. > > Of course, modules that haven't been migrated to use the "new" helpers > will still print without indentations. This will be one good reason to > migrate them. > > I think the runtime cost (when debug statements are disabled) of this is > reasonable, given the improvement in readability. There is the cost of > the conditionals (like standard debug statements), one more condition > (if (m_must_decrement_print_depth)) and the cost of constructing a stack > object, which means copying a fews pointers. > > Adding the print in fetch_inferior_event breaks some tests that use "set > debug infrun", because it prints a debug statement after the prompt. I > adapted these tests to cope with it, by using the "-prompt" switch of > gdb_test_multiple to as if this debug statement is part of the expected > prompt. It's unfortunate that we have to do this, but I think the debug > print is useful, and I don't want a few tests to get in the way of > adding good debug output. With this patch, gdb.threads/stepi-random-signal.exp becomes flaky. I folded this little fixup in the patch: commit 49c94827cbbe802726f177bc61c6c9d830907ffa Author: Simon Marchi Date: Tue Dec 22 16:33:40 2020 -0500 fixup Change-Id: Ibd2f622df3e76c873fcf82bca7c4c7900654647e diff --git a/gdb/testsuite/gdb.threads/stepi-random-signal.exp b/gdb/testsuite/gdb.threads/stepi-random-signal.exp index 9a8b38c2acf5..689de8fdc632 100644 --- a/gdb/testsuite/gdb.threads/stepi-random-signal.exp +++ b/gdb/testsuite/gdb.threads/stepi-random-signal.exp @@ -86,12 +86,13 @@ if {$prev_addr == ""} { set seen 0 set test "stepi" -if {[gdb_test_multiple "stepi" "$test" { +set prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$" +if {[gdb_test_multiple "stepi" "$test" -prompt $prompt { -re {\[infrun\] handle_signal_stop: random signal} { set seen 1 exp_continue } - -re "$gdb_prompt $" { + -re "$prompt$" { } }] != 0} { return Simon