Engineering, Smartly, Students & Careers

Git Bisect Debugging with Feature Branches

Inspectocat, courtsey of GitHub
Inspectocat, courtesy of GitHub

At Pedago, we follow the GitHub Flow model of software development. Changes to our app are made in feature branches, which are discussed, tested, code reviewed, and merged into master before deploying to staging and production. This approach has become pretty common, and in most cases does a good job of balancing our desire to ship quickly with the need to control code quality.

But, what happens when a bug inevitably creeps in, and you need to determine when it was introduced? This article describes how to apply git bisect in the presence of numerous feature branches to quickly detect when things went awry in your codebase.

Enter Git Bisect

git bisect is tool for automatically finding where in your source history a bug was introduced. It saves you the pain of manually checking out each revision yourself and keeping a scratchpad for which ones were good and bad.

Here’s how you get started:

# start up git bisect with a bad and good revision
git bisect start BAD_REVISION GOOD_REVISION

At this point, git is going to start checking out each revision and asking you if the commit is good or bad. You tell git this information by typing git bisect good or git bisect bad. Git then uses binary search (bisecting the history) to quickly find the errant commit.

You can also further automate things by giving git a script to execute against each revision with git bisect run. This allows git to take over the entire debugging process, flagging revisions as good or bad based on the exit code of the script. More on this below!

Example

Imagine you go back to work from a vacation and discover that the Rails specs are running much more slowly than you remember before you left. You know that the tests were fast at revision 75369f4a4c026772242368d870872562a3b693cb, your last commit before leaving the office.

Being a master of git, you reach for git bisect. You type:

git bisect start master 75369f4a4c026772242368d870872562a3b693cb

…and then for each revision git bisect gives you, you manually run rake spec with a stopwatch. If it’s too slow, you type git bisect bad, and if it’s fast you type git bisect good.

That’s kind of monotonous, though, and didn’t we mention something about automating things with a script above? Let’s do that.

Here’s a script that returns a non-zero error code if rake spec takes longer than 90 seconds:

#!/bin/bash

start=`date +%s`
rake spec
end=`date +%s`

runtime=$((end-start))


if [ "$runtime" -gt 90 ]
then
    echo TOO SLOW
    exit 1
fi

echo FAST ENOUGH
exit 0

Let’s say you save this script to /tmp/timeit.sh. You could use that instead of your stopwatch and keep manually marking commits as good and bad, but let’s go further and have git bisect do the marking for us:

git bisect run /tmp/timeit.sh

Now we’re talking! After waiting for a bit, git tells us that the errant revision is:

31c60257c790e5ab005d51d703bf4211f43b6539 is the first bad commit
commit 31c60257c790e5ab005d51d703bf4211f43b6539
Author: John Smith john@example.com
Date: Wed Jan 21 12:02:38 2015 -0500
   removing defunct jasmine-hacks.js
:040000 040000 94ff367b586ec62bacb3438e0bc36ae62f90da22 bd3b447e7fc8ce782a7a4c01d11d97383bf06309 M karma
bisect run success

OK, so that sounds good. But wait, that’s a commit that only affected javascript unit tests! How could that have caused a problem with the Ruby specs?

Damn You, Feature Branches

The problem is that git bisect is not confining itself to only the merge commits in master. When it narrows down the point in time when things got slow, it isn’t taking into account the fact that most revisions are confined to our feature branches and should be ignored when searching the history of changes to master.

What we really want is to only test the commits that were done directly in master, such as feature branch merges, and the various one-off changes we commit directly from time to time.

git rev-list Magic

Here’s a new strategy: using some git rev-list magic, we’ll find the commits that only exist in feature branches and preemptively instruct git bisect to skip them:

for rev in $(git rev-list 75369f4a4c026772242368d870872562a3b693cb..master --merges --first-parent); do
  git rev-list $rev^2 --not $rev^
done | xargs git bisect skip

In short, the above chunk of bash script:

  1. Gets all revisions between the known-good revision and master, filtering only those that are merges and following only the first parent commit, and then for each commit
  2. Gets the list of revisions that only exist within the merged branch, and then
  3. Feeds these branch-only revisions to git bisect skip.

Pulling It Together

Here’s the complete list of commands we’re going to run:

$ git bisect start master 75369f4a4c026772242368d870872562a3b693cb

$ for rev in $(git rev-list 75369f4a4c026772242368d870872562a3b693cb..master --merges --first-parent); do
>   git rev-list $rev^2 --not $rev^
> done | xargs git bisect skip

$ git bisect run /tmp/timeit.sh

This runs for a while, and completes with the following chunk of output:

Bisecting: 14 revisions left to test after this (roughly 4 steps)
[086e45] Merged in update_rails_4_2 (pull request #903)
running /tmp/timeit.sh
....................................................................
....................................................................
....................................................................
....................................................................
....................................................................
....................................................................
....................................................................
....................................................................
....................................................................
....................................................................
....................................
Finished in 1 minute 21.79 seconds (files took 6.63 seconds to load)
719 examples, 0 failures
Randomized with seed 54869

TOO SLOW

There are only 'skip'ped commits left to test.
The first bad commit could be any of:
342f9c65434bdeead74c25a038c5364512d6b67e
9b5395a9e1c225f8460f8dbb4922f52f9f1f5f1d
dcb1063e60dbcb352e9b284ace7c83e15faa93df
027ec5e59ca4c380adbd352b6e0b629e7b407270
1587aea093dffaac2cd655b3352f8739d7d482dc
2ff4dee35fd68b744f8f2fcd5451e05cb52bff87
73773eae4f6d283c3487d0a5aea0a605e25a8d3f
1cf615c6fa69e103aea3761feaf87e52f1565335
26d43d2060880cb2dbe07932fe4d073e3ccb7d44
293190779e33e26b9ceabfcff48021507591e9d1
77d504ee4b52b0869a543670cd9eb2fb42613301
3f25514f793e87549c9d64ddcfe87f580b29f37e
d43d1845b9fd6983ff323145f8e820e3aea52ebd
32a9e3c879546d202c27e85ab847ca9325977d5c
ea3e3760fb06e3141e5d12f054c1153e55b5cc67
9665813264a5e0d7489c43db871b87e319143220
b8f5106a8901d56621e72ba6b8bd44d4d5471dd2
086e45a2c0a2ed2cd26eeb48960c60048af87d0a
We cannot bisect more!
bisect run cannot continue any more

Hooray! We’ve found our offending commit: Merged in update_rails_4_2 (pull request #903). That makes sense—we upgraded RSpec and made a bunch of testing-related changes in that branch.

Furthermore, we see a list of skipped commits that git bisect didn’t test. This also makes sense—those commits are all within the update_rails_4_2 branch.

Conclusion

With a bit of git magic and some scripting, we’ve completely automated what could have been a very tedious exercise. Furthermore, thanks to the judicious use of git rev-list and git bisect skip, we’ve been able to cajole git into giving an answer that takes our branching strategy into account. Happy hacking!

Standard

One thought on “Git Bisect Debugging with Feature Branches

  1. Hey! This post could not be written any better! Reading through this
    post reminds me of my good old room mate! He always kept chatting about this.
    I will forward this article to him. Pretty sure he will have
    a good read. Thanks for sharing!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s