Blog

Debugging a duplicated behavior with GTInspector

I have just spent a beautiful 15 minutes tracking a bug down. It was so exciting that afterwards I decided to spend 2 days documenting the experience because I think it offers an elaborate example of how transformative development workflows can be with moldable tools in a live environment.

The bug in question was reported recently and it is related to the GTDebugger version that we introduced recently in Pharo.

The problem looks as follows. Triggering an action from the context menu of a stack seems to trigger twice the action. This is particularly visible when a window is spawned twice, such as when trying to see the implementors of a method from the stack.

Duplicated.png

This is a tricky problem, and it can come from all sorts of places. What is certain, is that at some point there are two executions of spawning the implementors window. The debugger defines this action in the GTMoldableDebugger>>browseMessages method. We put a breakpoint in the method, and indeed, it is being executed twice. Exploring the stack in both cases does not seem to reveal anything meaningful. The stack looks the same, so likely the problem comes from different objects, not from different messages.

To reason about this, we need a different presentation. Ideally, we would like to see the complete execution and check the points in which the execution branches. This information is not apparent in a classic debugger because it mainly shows only the active stack and we are interested in the tree.

Nevertheless, as the tree is what we care about we should be able to build it. To do this, we utilize the Beacon logging engine, and we replace the breakpoint with a logging statement that records the stack of contexts (ContextStackSignal log).

GTMoldableDebugger>>browseMessages
    "Present a menu of all messages sent by the current message.
    Open a message set browser of all implementors of the message chosen.”

    self currentMessageName ifNotNil: [
        ContextStackSignal log.
        self systemNavigation browseAllImplementorsOf: self currentMessageName ]

We turn on recording with RecordingBeacon start. We trigger the problem again: we inspect 42 answer, and then look for implementors. And we start exploring the recordings with GTInspector.

RecordingBeacon instance recordings collect: #stack

As expected there are two such collection of stacks, where the elements in each stack are context objects.

Playground1.png

We switch to the Raw inspector presentation of the collection object, and we try to visualize the entries in the two stack in one picture. We use the RTMondrian builder of Roassal to script the visualization. We concatenate the stack entries in one set, we draw edges between consecutive entries, and we arrange the graph in a tree. We use a set because some of the entries will be the same:

| view |
view := RTMondrian new.
view shape label text: [:each | each gtDisplayString truncate: 50 ] .
view nodes: (self first, self second) asSet.
self first
    overlappingPairsDo: [ :a :b |
        view edges
            connectFrom: [:x | b ]
            to: [:x | a ] ].
self second
    overlappingPairsDo: [ :a :b |
        view edges
            connectFrom: [:x | b ]
            to: [:x | a ] ].
view layout tree.
view.

Executing in place this script shows us the execution tree.

Playground2.png

There seems to be one place which branches the execution. Let’s zoom in to see the details.

Playground3.png

We see that the stack on both branches looks the same in terms of the executed methods. Let’s see if the difference is in the objects that are executing the two branches. For this, we inspect the context before the branching happens.

Playground4.png

We look at the receiver.

Playground5.png

It’s a SubscriptionRegistry which is used by objects interested in announcements. At a closer look, we notice that all announcement, such as GLMMenuItemSelected, seem to be registered twice. This points us towards the direction of a bug in Glamour, the browsing engine on top of which the GTDebugger is implemented. Glamour uses this type of announcements to bind what happens in the concrete Morphic world, and the logical model of the browser.

Armed with this new hypothesis, we can now create a smaller experiment in which we isolate the creation of a FastTable-based list in Glamour.

GLMCompositePresentation new
    with: [ :c |
        c fastList selectionAct: #inspect entitled: 'Value' ];
    openOn: (1 to: 42)

And indeed, in the resulting browser, executing the action via the contextual menu results in two inspector being opened. This means that the problem is actually not related to the GTDebugger but to Glamour. At the same time, a replacing fastList with list does not exhibit the problem, which means that our bug is located somewhere in the binding between FastTable and Glamour. This hypothesis would make sense given that the FastTable support was only recently introduced in Glamour and thus, it can still have bugs.

To figure it out, we would need to debug this. We could try putting a breakpoint in installActionsOnModel:fromPresentation:, but that would imply that if we would use the GTDebugger, our image would go in a loop with the breakpoint trying to spawn a debugger, and the opening of the debugger hitting a new breakpoint.

So, we take the same route as before, and we insert a logging statement that captures the current stack. This time, we look only at methods because it is probably enough:

installActionsOnModel: aMorphicModel fromPresentation: aPresentation
    MethodStackSignal log.
    aMorphicModel when: GLMMenuItemSelected do: [ :ann | ann action morphicActOn: aPresentation ].
    aMorphicModel when: GLMKeyStroke do: [ :ann | ann action actOn: aPresentation ].

This logging statement is placed deep in Glamour. As the GTInspector is based on Glamour, looking at the global log recorder would reveal many appearances of this log entry that are not related to our problem. So, we scope the recording only to the execution of the creation of our browser:

RecordingBeacon new
    runDuring: [
        GLMCompositePresentation new
            with: [ :c |
                c fastList
                    selectionAct: #inspect
                    entitled: 'Value' ];
            openOn: (1 to: 42) ].

Inspecting the result shows us the recordings.

Stack1.png

There are three such recordings. One is related to the window rendering, and two are related to FastTable. We explore the first one, and it is being called from the render: method. We explore the second one, and it comes from a method called dataSourceUpdated::

Stack2.png

We look at the dataSourceUpdated: method (notice how we essentially have a postmortem debugger in the inspector):

Stack3.png

And indeed, this method erroneously calls installActionsOnModel:fromPresentation::

dataSourceUpdated: announcement
    tableModel ifNotNil: [ self unsubscribeDataSource: tableModel ].
    tableModel := announcement newDataSource.
    self installActionsOnModel: tableModel fromPresentation: tableModel glamourPresentation.
    self initializeAnnouncementForDataSource

Now we know where the problem comes from, but we are not done yet. We still have to document our finding. In this case, the most appropriate way is to write a red functional test to capture the problem of multiple announcements with the same type being registered for a FastTable:

testNoDuplicateRegistrationOfAnnouncementsOnDataSource
    | table amountOfMenuItemSelectedSubscriptions |
    window := GLMCompositePresentation new
            with: [ :c |
                c fastList selectionAct: #inspect entitled: 'Value' ];
            openOn: (1 to: 42).
    table := self find: FTTableMorph in: window.
    amountOfMenuItemSelectedSubscriptions := table dataSource announcer subscriptions glmSubscriptions count: [ :each | each announcementClass = GLMMenuItemSelected ].
    self assert: amountOfMenuItemSelectedSubscriptions equals: 1

Then we remove the troubling line, and check that the test is green.

Now we are done.

Remarks

Let’s take a step back and look at the ingredients of this session. We guided all our steps through hypotheses following the humane assessment philosophy. As a consequence, at every point we knew where we were and why we were there. And we guided our actions by testing these hypotheses through custom made analyses.

To make this practical, we need tools that allow us to go through these scenarios inexpensively and live. With Pharo this is now a reality.

Looking at the details, our analysis involved actions such as:

  • recording the stack through a logger,
  • inspecting the stack postmortem with the inspector,
  • visualizing multiple stacks together, or
  • scoping the recording to a particular part of the execution.

Granted, these are typically perceived as advanced actions, but they really are not that complicated.

One thing that might appear hard is the idea of recording the execution context and then utilizing the inspector to debug. I reported on this technique before. On that occasion, I did it by directly inspecting thisContext. In the current case I used Beacon because (1) it makes it even easier to capture the stack as a log signal and offer it for later inspection (e.g., ContextStackSignal log), and (2) it has a convenient way to scope log capturing.

Another thing is the use of visualization which proved to be essential for solving our problem. It helped us analyze the two initial stacks in one meaningful picture that helped us quickly discover the point to look at (i.e., the branching point). This was possible exactly because we could embed that Roassal visualization right in place with little effort. It does require some learning, but together with the deep integration in the Glamorous Toolkit it brings with it a complete new way of exploring objects.

In my book, this session counts as cool. If you agree, we just labelled a debugging session as cool. And this is not at all an isolated case. It is actually rather common in my world. That is because debugging, and assessment in general, is an exciting activity. Can you say the same? If not, I invite you to start exploring what Pharo has to offer and go beyond the typical routine. You will be surprised.

Posted by Tudor Girba at 2 February 2016, 9:30 am with tags story, gt, spike, pharo, moose link
|

Spotting senders and references with GTSpotter

A recent discussion on the Pharo mailing list revealed that people would like to have the possibility of looking for senders of a symbol and references to a class in one step in Spotter. A complementary request was that when we know that we want to search only for senders, we do not want to search for anything else. Stefan Reichhart worked with me to provide the implementation for these use cases.

For example, searching for #ref Morph will reveal all references to the class Morph.

Spotter-references.png

Searching for #sen do: will reveal all senders of do:.

Spotter-senders.png

Some things left to do

There are some things that are not as nice as they can be.

First, the search only shows 5 entries even if there is plenty of space for showing more. This is because right now this limit is hardcoded in the definition of the search processor. We need to make this limit more fluid to also take into account the context of the search. That is, if there is only one category shown, we should be able to see all results.

Second, the categories are not easily discoverable. Ideally, we would like an autocompletion mechanism. This issue is addressed in more details below.

Third, an interesting observation came from Ben Coman and Stéphane Ducasse on the mailing list. Ben noted that it would be interesting to have a Cmd+n, the pervasive keybinding that searches for senders, be used to autocomplete #senders in the Spotter search. At the same time, Stef came up with the idea of providing unique one-letter shortcuts for common searches. For example, in the case of senders, we could use $n. These are things we will play with soon.

A look behind the scene

This example is a good opportunity to learn how Spotter works. Let’s take a step back and look at how this is implemented.

One question that pops up often is what a word containing a hash actually means. Let’s consider the senders example. #sen is simply a filter that matches the name of the search category (in our case #Senders). Given that there is only one category that begins with #sen, only the Senders search processor will be executed and only the corresponding result category will appear.

But, what would happen if we would use only #s? Let’s see.

Spotter-senders-only-s.png

In this case, we get two categories that appear: #Senders and #Selectors.

Now, the question is how do we know what are all the categories. This is not yet as discoverable as we would want from the user point of view. One way to find this out is by simply searching for a string and then browsing through the categories that appear for that search. Still, this will only provide a way to discover a list of the categories that matched the specific search, and not all possible categories.

At the moment, the most reliable way of finding what processors are available is by looking at the implementation. Wait, that is not as hard as it might appear, especially in a live environment that allows you to narrow down on important pieces of information. Let’s see. Every Spotter processor is defined as a method in a class corresponding to objects for which we want this processor to be active. For example, as our new senders processor is available in the first step, and as the context of that first step is provided by an instance of the GTSpotter class, it follows that we should find a method in that class. Here it is:

GTSpotter>>spotterForSendersFor: aStep
    <spotterOrder: 31>
    aStep listProcessor
        title: 'Senders';
        filter: GTNullFilter item: [ :filter :context |
            SystemNavigation default
                 allSendersToString: context textTrimmed
                 do: filter ];
        wantsToDisplayOnEmptyQuery: false

This relies on a small utility method:

SystemNavigation>>allSendersToString: aString do: aBlock
    aString isEmptyOrNil ifTrue: [ ^ self ].
    aString asSymbol ifNotNil: [ :symbol |
        self allBehaviorsDo: [ :class |
            class withMethodSender: symbol do: aBlock ] ]

Please note that the implementation of this use case took 13 lines of code.

To find all processors defined in the image, we simply need to find all usages of <spotterOrder:>. This can be achieved by using Spotter itself. First we search for spotterOrder: to find the pragma type:

SpotterOrder-pragmatype.png

And then we dive in to find the concrete pragmas:

SpotterOrder-pragmas.png

The same information can also be found by programmatically through the Playground and Inspector, like shown previously. In fact, given that this is such a relevant query for a programmer that wants to learn about Spotter, we already have a method that provides this (currently, there are 118 processors defined in the base Pharo image). For example, the following query will return the extensions that are defined in the top GTSpotter class (there are 24 of them in the base Pharo image):

GTSpotter spotterExtendingMethods select: [ :each |
     each methodClass = GTSpotter ]

But, that is not all. Given that we want to provide live documentation, inspecting the GTSpotter class, reveals a dedicated tag with these extensions as well:

Spotter-top-extensions.png

Summary

In this post we showed that Spotter now supports two new common use cases in one step: searching for senders and for references. While at first look, this appears as a new feature, in fact this is not a special behavior, but a generic mechanism in Spotter that allows us to obtain what we need in specific cases with very little programatic customization.

We took the opportunity to take a closer look at the implementation and we learnt that the extension for senders is 13 lines long (the one for references is similar). It is hard to imagine it going smaller than this.

Getting used to this way of thinking about tools does take some effort. To ease those first steps, we also went through different ways of discovering the existing implementation.

There are certainly more that we can do in this direction, but this example shows once again that going deep down the path of moldable tools in a live environment offers a significant departure from classic IDE concepts. It’s a fun way, and we think it’s worth learning it. At least, give it 5 minutes. Play with it. In fact, let’s play together.

Posted by Tudor Girba at 19 January 2016, 2:41 pm link
|

Spotting Pragma users with GTSpotter

Finding pieces of code that are annotated in a certain way can be challenging in many IDEs. In Pharo, this is fairly straightforward using GTSpotter.

For example, how can we find all methods annotated with <menu>?

Spawn Spotter, and type menu #pr. This will search for menu and show only the results from categories starting with pr (from Pragmas).

Pragmas.png

Then simply dive in (Cmd+RightArrow) the menu Pragma to find the concrete users.

Pragma-users.png

Posted by Tudor Girba at 9 January 2016, 10:41 pm link
|

GTDebugger in Pharo 5.0

After GTInspector, GTPlayground, and GTSpotter, it is time for GTDebugger to enter the main Pharo arena. GTDebugger is part of the Glamorous Toolkit project and it is mainly driven by Andrei Chis. Since several years it acts as the default debugger in the Moose environment. Still, even if it is a mature implementation, the debugger is a critical development tool in Pharo and a new solution can affect significantly the workflow of developers. This post offers an overview of these differences and some practical information.

We should note from the start that, to make the transition smoother, GTDebugger can be easily turned on/off through a setting.

Gtdebugger-settings.png

The generic stack debugger

The default incarnation of the GTDebugger comes with a slightly different interface than the previous debugger, so let’s take a tour.

Similar to the classic debugger structure, the stack is on top-left, and code is on the top-right, and the variables are offered at the bottom.

In the current state, the GTDebugger is implemented in Glamour, and this influences the way actions are being distributed. Thus, the stack manipulation actions (e.g., step into or step over) are offered in the stack pane, while code related actions (e.g., browse) are offered in the code pane.

Gtdebugger-zerodivide-onlyvars.png

One thing to note is that the variables at the bottom are offered in a fully functional GTInspector.

Gtdebugger-zerodivide-inspector.png

Another particularity is that the stack highlights some of the entries. For example, in the below screenshot you can observe a debugging session corresponding to the start of an inspector. The second method activation is highlighted in blue to denote that it is a method situated in the same class as the current method, and the following two are marked with black to show that they belong to the same package:

Gtdebugger-default-highlight.png

The moldable debugger

While the generic debugger has only minor differences to the classic one, the main difference comes from what cannot be easily seen. Like all other tools from the Glamorous Toolkit, GTDebugger is moldable by design. In the case of the inspector each object can influence the displayed presentations. In the case of the debugger, it is the execution context that can decide the presentation and interaction logic.

This means that we can easily create custom debuggers for different libraries. The main distribution comes with two such custom debuggers: the SUnit debugger, and the bytecode debugger. These are both useful and provide examples of how the debugger can be customized.

The SUnit debugger) provides a simple customization that shows a diff view when assert:equals: is present in the debugged stack. This might sound trivial, and it indeed it is relevant in only some cases, but detecting fine-grained differences between the expected result and the provided result is a problem is every IDE I know. It is indeed simple, but it is one of those examples of how simple things should actually be simple. This is important because simple things add up and they end up constructing the overall user experience.

This extension is found in the GT-SUnitDebugger package and it totals 132 lines of code. That should fall in the inexpensive category.

Let’s now take a look at the bytecode debugger. This one again customizes the presentation in a couple of ways:

  • a new bytecode view appears to the right of the code pane, and
  • the inspector variables appear listed with more bytecode-relevant labels (e.g., 1, rcv1).

Gtdebugger-bytecode.png

Another relevant part in a debugger is the way we can navigate the execution space. Thus, actions such as 'step over' should be controllable by the programmer of a debugger. In the case of the bytecode debugger, a desired action is to be able to step to a specific bytecode.

Gtdebugger-bytecode-actions.png

The implementation of this debugger consists of 165 lines of code.

Summary

The GTDebugger is a new take on debugging. At first glance, it looks similar to any other debugger, but its moldable nature and customization costs measured in only hundreds of lines of code paves the way for a significant departure from classic debugging.

To get you started, the core distribution comes with two concrete custom incarnations. Actually there are three: the generic stack debugger is implemented in the same way. There exists others for different libraries, such as PetitParser or Glamour, but these default ones already offer a beginning of documentation.

You can read more about the GTDebugger here:

Posted by Tudor Girba at 8 January 2016, 11:01 am with tags gt, moose, analysis, pharo link
|

Evaluating the reimplementation of key Context methods in Pharo

The Context class in Pharo is an essential one that models the activation of either a method or a block. A context instance can be obtained through the thisContext variable from anywhere in the code and it offers an entry point to manipulating the current execution.

For example, it offers information about the sender or about the receiver of the last message. This means that this object offers the entry point for debugging support: essentially the debugger is an inspector of this object. That means that you can do interesting things, such as debugging the debugger with the inspector.

What can I say. It’s a fun object to play with.

But, recently I stumbled across a little problem that Eliot pointed me to. Essentially, for it to work properly, the context object should directly work with the virtual machine and restrain itself from sending messages to the current receiver object. Unfortunately, in Pharo, this is not yet the case, and this leads to unwanted side effects.

Let's identify the culprit methods. Essentially, we want to find all non-extension methods that either:

  • send a message to self receiver, or
  • send a message to the receiver instance variable.

Of course, we do not want to rely on code reading. Even if the class is not very large, code reading is just not appropriate. Instead, we can write a query over the abstract syntax trees of all methods in the Context class:

Context methods select: [ :method |
    method package = method methodClass package and: [
        method parseTree doSemanticAnalysis allChildren
            anySatisfy: [ :each |
            each isMessage and: [
                (each receiver isMessage and: [
                    each receiver selector = #'receiver' ])
                or: [
                    each isMessage and: [
                        each receiver isVariable and: [
                            each receiver isInstance and: [
                                each receiver name = #receiver
                                ] ] ] ] ] ] ] ]

This query is rather long. It took me about 7 minutes. And I did not write it all at once. The way I wrote this was essentially by picking one method that I knew was problematic, and looking at its abstract syntax tree with the GTInspector. This allowed me to understand how the pattern I was looking for is actually represented in the tree, and write the query for it.

Onemethod.png

Inspecting the result of the above query in the GTInspector offers us a quick browser for only the problematic methods. Now we can read the code.

Query.png

Once we have this query, besides obtaining support for browsing, we can also use it for regression testing to ensure that such an important constraint is preserved in the future.

Posted by Tudor Girba at 29 November 2015, 4:57 pm link
|
<< 1 2 3 4 5 6 7 8 9 10 >>