git-bisect failure

git-bisect failure

[Andrew Morton]

Using git-core-0.99.6 I tried to locate a bug using git's bisection
searching.

It gave the wrong answer.   It ended up claiming the bug was in


tree ea7b1763aa0e0d36b52fa245449c79338fe735b3
parent e9f86e351fda5b3c40192fc3990453613f160779
author Zachary Amsden <zach@vmware.com> Sun, 04 Sep 2005 05:56:47 -0700
committer Linus Torvalds <torvalds@evo.osdl.org> Mon, 05 Sep 2005 14:06:13 -0700

[PATCH] x86: introduce a write acessor for updating the current LDT



Whereas the bug was really in


tree 090c471fdb44d8fe88c52e95be0e8e43e31fcd5a
parent d7271b14b2e9e5905aba0fbf5c4dc4f8980c0cb2
author Zwane Mwaikambo <zwane@arm.linux.org.uk> Sun, 04 Sep 2005 05:56:51 -0700
committer Linus Torvalds <torvalds@evo.osdl.org> Mon, 05 Sep 2005 14:06:13 -0700

[PATCH] i386 boottime for_each_cpu broken


Which is off-by-two, iirc.


Exact sequence:

bix:/usr/src/git26> git bisect start
bix:/usr/src/git26> git bisect good 02b3e4e2d71b6058ec11cc01c72ac651eb3ded2b
bix:/usr/src/git26> git bisect bad 4e1491847ef5ca1c5a661601d5f96dcb7d90d2f0
Bisecting:     901 revisions left to test after this
bix:/usr/src/git26> git bisect good
Bisecting:     451 revisions left to test after this
bix:/usr/src/git26> git bisect bad 
Bisecting:     219 revisions left to test after this
bix:/usr/src/git26> git bisect bad
Bisecting:     110 revisions left to test after this
bix:/usr/src/git26> git bisect bad
Bisecting:      55 revisions left to test after this
bix:/usr/src/git26> git bisect bad
Bisecting:      28 revisions left to test after this
bix:/usr/src/git26> git bisect good
Bisecting:      14 revisions left to test after this
bix:/usr/src/git26> git bisect good
Bisecting:       7 revisions left to test after this
bix:/usr/src/git26> git bisect good
Bisecting:       3 revisions left to test after this
bix:/usr/src/git26> git bisect bad 
Bisecting:       2 revisions left to test after this
bix:/usr/src/git26> git bisect good
f2f30ebca6c0c95e987cb9a1fd1495770a75432e is first bad commit
diff-tree f2f30ebca6c0c95e987cb9a1fd1495770a75432e (from e9f86e351fda5b3c40192fc3990453613f160779)
Author: Zachary Amsden <zach@vmware.com>
Date:   Sat Sep 3 15:56:47 2005 -0700

    [PATCH] x86: introduce a write acessor for updating the current LDT
    


I don't think I screwed anything up.

Re: git-bisect failure

[Junio C Hamano]

Thanks for the note.  If somebody else does not get around to it
before me, I'll take a look later today after work.

Re: git-bisect failure

[Junio C Hamano]

bix:/usr/src/git26> git bisect bad
Bisecting:      55 revisions left to test after this

At this point, you marked 4c139862b8831261d57de02716b92f82e5fb463b
"[PATCH] xtensa: delete accidental file" is already bad.  And the last
known good commit is b749bfcd1be72f8cb8310e1cac12825bda029432 "[PATCH]
ppc64: update xmon helptext".  The commit between these is just a
straight sequence (no branches), so running "git bisect visualize"
gives me a nice single strand of pearls.

bix:/usr/src/git26> git bisect bad
Bisecting:      28 revisions left to test after this

With this, you marked "[PATCH] i386 boottime for_each_cpu broken" is
bad.  "Reread references" in the running gitk shows me that the range
between bad and good halved.

bix:/usr/src/git26> git bisect good
Bisecting:      14 revisions left to test after this

Marked "[PATCH] mips: remove timex.h for vr41xx" good.

bix:/usr/src/git26> git bisect good
Bisecting:       7 revisions left to test after this

Marked "[PATCH] i386: cleanup serialize msr" good.

bix:/usr/src/git26> git bisect good
Bisecting:       3 revisions left to test after this

Marked "[PATCH] x86: privilege cleanup" good.

bix:/usr/src/git26> git bisect bad 
Bisecting:       2 revisions left to test after this

Marked "[PATCH] x86: introduce a write acessor for updating the
current LDT" bad.

Just after you marked "[PATCH] x86: privilege cleanup" as good, the
list of suspects looked like this (time flows bottom to top):

bad  [PATCH] i386 boottime for_each_cpu broken
     [PATCH] i386: encapsulate copying of pgd entries
     [PATCH] x86 NMI: better support for debuggers
???  [PATCH] x86: introduce a write acessor for updating the current LDT
     [PATCH] x86: remove redundant TSS clearing
     [PATCH] x86: make IOPL explicit
good [PATCH] x86: privilege cleanup

and you said the middle one is already bad here.  We are tracking
regression, so "privilege cleanup" was good and in the course of
somewhere from there to "i386 boottime for_each_cpu broken" which is
bad, a breakage happened.  You marked the "updating the current LDT"
one as bad, which to me looks like it was already broken at that point.

After that, you say:
bix:/usr/src/git26> git bisect good

to mark "[PATCH] x86: remove redundant TSS clearing" as good,
which means "redundant TSS" was good and "current LDT" was bad,
and they are back to back, so it looks like the bug was
introduced by the "LDT", which is what you got.  So it _might_
be possible that you said "current LDT" was bad when it was
actually good.  That is one possible explanation.

Another possibility is that the symptom you were tracking was
not a single regression that was introduced with a single patch.
Could it be possible that "the current LDT" did not pass your
test but from different bug, which was fixed by either "x86 NMI"
or "encapsulate copying pgd"?  Sorry I am not a kernel developer
so I cannot judge if the above is plausible or not.

In any case, there is one caveat about bisection bug search.  It
assumes that you are tracking a single regression that was
introduced, and there is no funny interaction of bugs hiding
each other -- this may not hold true in the real life.  IOW,
something like this could be possible:

BAD  [PATCH] i386 boottime for_each_cpu broken
good [PATCH] i386: encapsulate copying of pgd entries
bad  [PATCH] x86 NMI: better support for debuggers
BAD  [PATCH] x86: introduce a write acessor for updating the current LDT
good [PATCH] x86: remove redundant TSS clearing
good [PATCH] x86: make IOPL explicit
GOOD [PATCH] x86: privilege cleanup

I marked the ones bisect told you to test in Capital letters, and a
good/bad which was never tested in lowercase.  If the bug pattern is
not "up to here everything is good but after that things start to
break", then bisect, by its nature of skipping the check to narrow the
range down fast, would miss the real transition from good to bad.

Re: git-bisect failure

[Andrew Morton]

Junio C Hamano <junkio@cox.net> wrote:
>
> So it _might_
>  be possible that you said "current LDT" was bad when it was
>  actually good.  That is one possible explanation.

I agree.  Mea culpa.  Sorry.

Re: git-bisect failure

[Linus Torvalds]

On Sat, 10 Sep 2005, Andrew Morton wrote:
>
> Junio C Hamano <junkio@cox.net> wrote:
> >
> > So it _might_
> >  be possible that you said "current LDT" was bad when it was
> >  actually good.  That is one possible explanation.
> 
> I agree.  Mea culpa.  Sorry.

Well, this was actually something I hit when testign bisection too: it 
_is_ very unforgiving of mistakes.

That _may_ be something fundamental (hey, the point of bisection is that
you can get a lot of work done thanks to the log2(n) behaviour, but it
also means that a mistake ends up being easily multiplied). But on the 
other hand, maybe there could be nicer interfaces.

In particular, I suspect that we should save off the sequence of good/bad 
markers, so that it can be more easily re-created. Right now we only track 
the last "bad" marker, and we don't keep track of the order of the ones 
marked good. That's technically _sufficient_ for the job, but maybe we 
should have more of an audit trail.

With an audit trail, people could re-do the bisection if something goes 
wrong. Right now, if you by mistake mark something bad, and you 
immediately realize that it was a mistake, you can't undo it - because the 
old bad state was overwritten.

So the bisection algorithm may have done the right thing from a technical 
standpoint, but I suspect it could be made to be a bit more forgiving, or 
at least when somebody realizes that bisection didn't work right, we could 
have the trail of good/bad markings to try to debug what happened...

		Linus

Re: git-bisect failure

[Andrew Morton]

Linus Torvalds <torvalds@osdl.org> wrote:
>
> On Sat, 10 Sep 2005, Andrew Morton wrote:
>  >
>  > Junio C Hamano <junkio@cox.net> wrote:
>  > >
>  > > So it _might_
>  > >  be possible that you said "current LDT" was bad when it was
>  > >  actually good.  That is one possible explanation.
>  > 
>  > I agree.  Mea culpa.  Sorry.
> 
>  Well, this was actually something I hit when testign bisection too: it 
>  _is_ very unforgiving of mistakes.

Yes.  That was my third attempt.  You basically _have_ to write down the
good/bad sequence as you go.  One slip and you've blown an hour's work.

>  So the bisection algorithm may have done the right thing from a technical 
>  standpoint, but I suspect it could be made to be a bit more forgiving, or 
>  at least when somebody realizes that bisection didn't work right, we could 
>  have the trail of good/bad markings to try to debug what happened...

Yup.  Simply keeping a little log file would suffice.

Re: git-bisect failure

[Linus Torvalds]

On Sat, 10 Sep 2005, Andrew Morton wrote:
> 
> Yup.  Simply keeping a little log file would suffice.

This is a _very_ cheesy and untested patch.

Oh, btw, it also fixes "git bisect reset" - we used to remove the file 
"refs/reads/bisect", not "refs/heads/bisect". 

Cheesy, cheesy, cheesy,

		Linus "not proud" Torvalds

---
Subject: Keep bisect event log

This keeps an event log in refs/bisect/log, which tracks what bisections 
have been done. We could eventually have a "git bisect replay" or 
somethign similar that actually uses it - for now we just have a command 
to show the log: "git bisect log".

Signed-off-by: Linus Torvalds <torvalds@osdl.org>
---
diff --git a/git-bisect.sh b/git-bisect.sh
--- a/git-bisect.sh
+++ b/git-bisect.sh
@@ -8,7 +8,8 @@ git bisect bad [<rev>]		mark <rev> a kno
 git bisect good [<rev>...]	mark <rev>... known-good revisions.
 git bisect next			find next bisection to test and check it out.
 git bisect reset [<branch>]	finish bisection search and go back to branch.
-git bisect visualize            show bisect status in gitk.'
+git bisect visualize            show bisect status in gitk.
+git bisect log                  show bisect log.'
     exit 1
 }
 
@@ -67,6 +68,7 @@ bisect_bad() {
 		usage ;;
 	esac || exit
 	echo "$rev" > "$GIT_DIR/refs/bisect/bad"
+	echo "bad $rev" >> "$GIT_DIR/refs/bisect/log"
 	bisect_auto_next
 }
 
@@ -81,6 +83,7 @@ bisect_good() {
 	do
 		rev=$(git-rev-parse --verify "$rev") || exit
 		echo "$rev" >"$GIT_DIR/refs/bisect/good-$rev"
+		echo "good $rev" >> "$GIT_DIR/refs/bisect/log"
 	done
 	bisect_auto_next
 }
@@ -149,7 +152,11 @@ bisect_reset() {
 	esac
 	git checkout "$branch" &&
 	rm -fr "$GIT_DIR/refs/bisect"
-	rm -f "$GIT_DIR/refs/reads/bisect"
+	rm -f "$GIT_DIR/refs/heads/bisect"
+}
+
+bisect_log() {
+	cat "$GIT_DIR/refs/bisect/log"
 }
 
 case "$#" in
@@ -172,6 +179,8 @@ case "$#" in
 	bisect_visualize "$@" ;;
     reset)
         bisect_reset "$@" ;;
+    log)
+        bisect_log "$@" ;;
     *)
         usage ;;
     esac

Re: git-bisect failure

[Junio C Hamano]

Andrew Morton <akpm@osdl.org> writes:

>>  So the bisection algorithm may have done the right thing from a technical 
>>  standpoint, but I suspect it could be made to be a bit more forgiving, or 
>>  at least when somebody realizes that bisection didn't work right, we could 
>>  have the trail of good/bad markings to try to debug what happened...
>
> Yup.  Simply keeping a little log file would suffice.

Will do.  Thanks.

Re: git-bisect failure

[Junio C Hamano]

The one I am going to put in the "master" branch later today
will give you the attached transcript.

Highlights:

 * After bisecting and checking out a revision to try out, it
   tells you which revision you are about to test.

 * It keeps a log in $GIT_DIR/BISECT_LOG as you suggested.  This
   is a shell script so you can remove everything after you want
   to redo in an editor, save the result in a different file,
   and run it -- do not edit the file in place and run it
   because the re-run will overwrite the log file ;-).

 * Even better, 'git bisect' has a new command 'replay'.  After
   editing the log file from the previous run and saving it in a
   different file, run 'git bisect replay $that_file'.  This
   avoids checking things out repeatedly, only to overwrite with
   the next revision to be tested.

: siamese; git-bisect reset 
: siamese; git-bisect good 02b3e4e2d71b6058ec11cc01c72ac651eb3ded2b
You need to start by "git bisect start"
Do you want me to do it for you [Y/n]? y
: siamese; git-bisect bad 4e1491847ef5ca1c5a661601d5f96dcb7d90d2f0
Bisecting: 901 revisions left to test after this
[b749bfcd1be72f8cb8310e1cac12825bda029432] ppc64: update xmon helptext
: siamese; git-bisect good b749bfcd1be72f8cb8310e1cac12825bda029432
Bisecting: 451 revisions left to test after this
[439c430e3d448b16112de3f3d92bef6ee2639d89] arm26: one -g is enough for everyone
: siamese; git-bisect bad 439c430e3d448b16112de3f3d92bef6ee2639d89
Bisecting: 219 revisions left to test after this
[fae91e72b79ba9a21f0ce7551a1fd7e8984c85a6] I2C: Drop I2C_DEVNAME and i2c_clientname
: siamese; git-bisect bad fae91e72b79ba9a21f0ce7551a1fd7e8984c85a6
Bisecting: 110 revisions left to test after this
[4c139862b8831261d57de02716b92f82e5fb463b] xtensa: delete accidental file
: siamese; git-bisect bad 4c139862b8831261d57de02716b92f82e5fb463b
Bisecting: 55 revisions left to test after this
[4ad8d38342430f8b52f7a8458dce90caf8c8ca64] i386 boottime for_each_cpu broken
: siamese; git-bisect bad 4ad8d38342430f8b52f7a8458dce90caf8c8ca64
Bisecting: 28 revisions left to test after this
[6fe7f2578fb4903af79abeb29bb9b9ab5eace1b5] mips: remove timex.h for vr41xx
: siamese; git-bisect good 245067d1674d451855692fcd4647daf9fd47f82d
Bisecting: 7 revisions left to test after this
[0998e4228aca046fbd747c3fed909791d52e88eb] x86: privilege cleanup
: siamese; git-bisect good 0998e4228aca046fbd747c3fed909791d52e88eb
Bisecting: 3 revisions left to test after this
[f2f30ebca6c0c95e987cb9a1fd1495770a75432e] x86: introduce a write acessor for updating the current LDT
: siamese; git-bisect bad f2f30ebca6c0c95e987cb9a1fd1495770a75432e
Bisecting: 2 revisions left to test after this
[e9f86e351fda5b3c40192fc3990453613f160779] x86: remove redundant TSS clearing
: siamese; cat .git/BISECT_LOG 
git-bisect start
# good: [02b3e4e2d71b6058ec11cc01c72ac651eb3ded2b] Linux v2.6.13
git-bisect good 02b3e4e2d71b6058ec11cc01c72ac651eb3ded2b
# bad: [4e1491847ef5ca1c5a661601d5f96dcb7d90d2f0] Fix up ARM serial driver compile failure
git-bisect bad 4e1491847ef5ca1c5a661601d5f96dcb7d90d2f0
# good: [b749bfcd1be72f8cb8310e1cac12825bda029432] ppc64: update xmon helptext
git-bisect good b749bfcd1be72f8cb8310e1cac12825bda029432
# bad: [439c430e3d448b16112de3f3d92bef6ee2639d89] arm26: one -g is enough for everyone
git-bisect bad 439c430e3d448b16112de3f3d92bef6ee2639d89
# bad: [fae91e72b79ba9a21f0ce7551a1fd7e8984c85a6] I2C: Drop I2C_DEVNAME and i2c_clientname
git-bisect bad fae91e72b79ba9a21f0ce7551a1fd7e8984c85a6
# bad: [4c139862b8831261d57de02716b92f82e5fb463b] xtensa: delete accidental file
git-bisect bad 4c139862b8831261d57de02716b92f82e5fb463b
# bad: [4ad8d38342430f8b52f7a8458dce90caf8c8ca64] i386 boottime for_each_cpu broken
git-bisect bad 4ad8d38342430f8b52f7a8458dce90caf8c8ca64
# good: [245067d1674d451855692fcd4647daf9fd47f82d] i386: cleanup serialize msr
git-bisect good 245067d1674d451855692fcd4647daf9fd47f82d
# good: [0998e4228aca046fbd747c3fed909791d52e88eb] x86: privilege cleanup
git-bisect good 0998e4228aca046fbd747c3fed909791d52e88eb
# bad: [f2f30ebca6c0c95e987cb9a1fd1495770a75432e] x86: introduce a write acessor for updating the current LDT
git-bisect bad f2f30ebca6c0c95e987cb9a1fd1495770a75432e
: siamese; sed -e '$d' .git/BISECT_LOG >./++bisect-replay ;# botched the last one
: siamese; git-bisect reset
: siamese; sh ./++bisect-replay ;# we could replay with shell
Bisecting: 901 revisions left to test after this
[b749bfcd1be72f8cb8310e1cac12825bda029432] ppc64: update xmon helptext
Bisecting: 451 revisions left to test after this
[439c430e3d448b16112de3f3d92bef6ee2639d89] arm26: one -g is enough for everyone
Bisecting: 219 revisions left to test after this
[fae91e72b79ba9a21f0ce7551a1fd7e8984c85a6] I2C: Drop I2C_DEVNAME and i2c_clientname
Bisecting: 110 revisions left to test after this
[4c139862b8831261d57de02716b92f82e5fb463b] xtensa: delete accidental file
Bisecting: 55 revisions left to test after this
[4ad8d38342430f8b52f7a8458dce90caf8c8ca64] i386 boottime for_each_cpu broken
Bisecting: 28 revisions left to test after this
[6fe7f2578fb4903af79abeb29bb9b9ab5eace1b5] mips: remove timex.h for vr41xx
Bisecting: 7 revisions left to test after this
[0998e4228aca046fbd747c3fed909791d52e88eb] x86: privilege cleanup
Bisecting: 3 revisions left to test after this
[f2f30ebca6c0c95e987cb9a1fd1495770a75432e] x86: introduce a write acessor for updating the current LDT
: siamese; git-bisect reset
: siamese; git-bisect replay ./++bisect-replay ;# but replay command is faster.
Bisecting: 3 revisions left to test after this
[f2f30ebca6c0c95e987cb9a1fd1495770a75432e] x86: introduce a write acessor for updating the current LDT
: siamese; exit