Ticket #116 (closed bug: fixed)

Opened 13 years ago

Last modified 13 years ago

intermittent failure of t/pmc/freeze_25.pir

Reported by: Infinoid Owned by:
Priority: normal Milestone:
Component: none Version:
Severity: medium Keywords:
Cc: Language:
Patch status: Platform:

Description

I am getting an intermittant failure in this test, and others in #parrot have confirmed it. The failure is in a Hash PMC, which, after being frozen/thawed, in some cases does not return the data that was put into the original hash.

The test is supposed to output two lines of similar numbers, as follows: 1 2 3 6 1 2 3 6

There are apparently 3 possible outcomes. The first is that the hash returns the same data that was put into it, and thus the second line of output is "1 2 3 6". This happens about 80% of the time. The second and third outcomes are failures, which look like:

1 2 3 6 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 125 (t/pmc/freeze_25.pir:45) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13)

and

1 2 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 105 (t/pmc/freeze_25.pir:38) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13)

(the difference being whether the "3 6" is printed or not.)

I have bisected this issue, and it was introduced in r34127.

Attachments

log.txt Download (3.9 KB) - added by Infinoid 13 years ago.
shell log
pathological_case.patch Download (0.6 KB) - added by Infinoid 13 years ago.
Load the hash seed with a known-bad value, to make the test fail every time.
freeze_25_say_output.txt Download (9.7 KB) - added by geraud 13 years ago.

Change History

follow-up: ↓ 2   Changed 13 years ago by Infinoid

One interesting thing is, it seems highly time-dependent. If you run it quickly from a loop, failures are clumped into certain seconds. I believe the failure is directly dependent on the specific value passed to Parrot_srand, which is just the current UNIX timestamp. See the following shell log:

infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835245 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835245 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835245 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835245 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835245 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835246 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835246 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835246 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835246 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835246 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835247 1 2 3 6 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 125 (t/pmc/freeze_25.pir:45) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13) infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835247 1 2 3 6 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 125 (t/pmc/freeze_25.pir:45) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13) infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835247 1 2 3 6 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 125 (t/pmc/freeze_25.pir:45) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13) infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835247 1 2 3 6 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 125 (t/pmc/freeze_25.pir:45) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13) infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835247 1 2 3 6 3 6 Null PMC access in get_integer_keyed() current instr.: 'test' pc 125 (t/pmc/freeze_25.pir:45) called from Sub 'main' pc 42 (t/pmc/freeze_25.pir:13) infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835248 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835248 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835248 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835248 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835248 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835249 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835249 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835249 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835249 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835249 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835250 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835250 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835250 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835250 1 2 3 6 1 2 3 6 infinoid@chirp test % perl -e 'print(time(),"\n")'; ./parrot t/pmc/freeze_25.pir 1230835250 1 2 3 6 1 2 3 6

in reply to: ↑ 1   Changed 13 years ago by Infinoid

Replying to Infinoid:

See the following shell log:

Uck, that came out formatted wrong. I'll attach the log as a text file.

Changed 13 years ago by Infinoid

shell log

follow-up: ↓ 4   Changed 13 years ago by allison

This test failure goes away if you run 'make realclean'. It's probably a dependency problem in the Makefile.

in reply to: ↑ 3   Changed 13 years ago by Infinoid

Replying to allison:

This test failure goes away if you run 'make realclean'. It's probably a dependency problem in the Makefile.

Not for me. I've done probably around 200 realcleans during the testing and debugging of this; it is definitely repeatable.

It is dependent on the particular value of the hash seed in use; I'll attach a small patch that makes it crash every time for me (on gentoo amd64).

Changed 13 years ago by Infinoid

Load the hash seed with a known-bad value, to make the test fail every time.

  Changed 13 years ago by coke

I'm seeing it on a build in a fresh checkout on osx/intel:

 http://smolder.plusthree.com/app/public_projects/report_details/11636#first_failure

  Changed 13 years ago by jkeenan

  • summary changed from intermittant failure of t/pmc/freeze_25.pir to intermittent failure of t/pmc/freeze_25.pir

  Changed 13 years ago by cotto

The now-failing test was added way back in r13785. The commit message mentions a reentrancy bug concerning the visit_info struct, which may or may not be a red herring.

Changing the hash seed in r13785 to use some pathological cases didn't trigger the bug.

The presence and position of &!ws has a strange effect on the test result, but I don't have tuits to say more than that.

  Changed 13 years ago by geraud

I encountered this problem yesterday and tried to add debug statements to see if I could catch something.

Attached is the result of my uninformed attempt to find something relevant.

Hope this can be of any help for the more savvy people.

Changed 13 years ago by geraud

  Changed 13 years ago by cotto

  • status changed from new to closed
  • resolution set to fixed

The problem was that freeze/thaw (and clone) of a Hash resulted in a different internal ordering of the entries if sequential keys weren't stored in sequential buckets (i.e. they wrapped). r35109 fixes this by changing freeze and clone to copy elements by iterating through hash->bs. This means that the in-memory position of entries should always be identical in cloned or frozen/thawed Hashes.

The reason for the test failures was that the different internal ordering was messing up Class attribute lookups. I didn't bother finding out exactly why this happened. It may be worth looking into.

I added a couple new tests to t/pmc/hash.t to make sure internal order stays consistent across freeze/thaw and clone.

Note: See TracTickets for help on using tickets.