Bug - Fixed Race condition between multiple matchers executing in parallel

Qualidus

New member
Using the latest version of KoLMafia (15.9 r12000) on both Java7 and Java6 (1.6.0_43-b01), it seems that if two matchers are executing in parallel, unpredictable results can occur.

The practical case where this is occurring is when a relay override script executes at the same time as a long running script. Specifically the scripts I'm seeing this issue with is between CHIT (replaces charpane.php) and BatBrain.

The random errors I see typically result in random string corruption where strings in one script override strings in another script. For example, BatBrain will sometimes attempt to process the familiar HTML strings due to this corruption. More unusual is that random zlib vars will get created or other variables also get randomly corrupted.

Example of odd zlib behavior:

The command (in CHIT): setvar("chit.walls.layout","modifiers,helpers,effects");
Resulted in:
> New ZLib string setting: -{15,17.5,20} => modifiers,helpers,effects

Here a BatBrain 'spread' appears to have wandered into CHIT's setting of variables.

Unfortunately, as it's rather random which strings get replaced and when this problem even occurs, it is difficult to replicate the string corruption and collect sufficient data.

However, I've been able to recreate some errors when running multiple matchers in parallel using some simple test scripts instead of the original scripts mentioned.

Pardon the crude code.

charpane.ash (Simulates a script using matchers):
Code:
void main()
{
	item i;
	
  foreach i in $items[]
  {
  	string itemName = to_string(i);
  	string itemNum = to_int(i);
  	string loopNum = 1;
  	string line = loopNum + ":" + itemNum + ":" + itemName + "<br>";
  	matcher extract;
  	extract = create_matcher("([^:]*):([^:]*):([^:]*)", line);
  	
  	while(extract.find())
  	{
  		writeln("Number groups: " + group_count(extract) + "<br>");
  		writeln("[" + extract.group(1) + "] " + extract.group(2) + " - " + extract.group(3) + "<br>");
  	}
  	writeln(line) ;
  }
}

test-race.ash (simulates a long running script using matchers like BatBrain):
Code:
void main()
{
	item i;
	
  foreach i in $items[]
  {
  	foreach j in $items[]
  	{
	  	string itemName = to_string(i);
	  	string itemNum = to_int(i);
	  	string loopNum = to_int(j);
	  	string line = itemNum + ":" + loopNum + ":" + itemName + "\n";
	  	matcher extract;
	  	extract = create_matcher("([^:]*):([^:]*):([^:]*)", line);
	  	
	  	while(extract.find())
	  	{
	  		print("Number groups: " + group_count(extract));
	  		print("[" + extract.group(1) + "]" + extract.group(2) + "-" + extract.group(3));
	  	}
	  	print(line);
	  }
  }
}

Execute test-race.ash then reload the main relay browser page such that charpane.ash is refreshed (may take a few tries). This usually results in one of these unusual errors:
No match attempted or previous match failed (test-race.ash, line 20)
No match attempted or previous match failed (charpane.ash, line 17)
Group 3 requested, but pattern only has 3 groups (charpane.ash, line 17)
 

roippi

Developer
What makes this the fault of matchers? The first example you posted with zlib does not appear to involve matchers.
 

Qualidus

New member
I dug a little further into the issue regarding the zlib example and that one doesn't seem to be caused by matchers but replace_string instead. Similar behavior is seen when running multiple replace_strings in parallel. This seems to be the root cause of the string corruption and relates specifically to the zlib example as the setvar function in zlib replaces all underscores in the variable name. If another replace_string is running at the same time, the results of that string can overwrite the original result.

More sample scripts:
Charpane.ash:
Code:
void main()
{
	item i;
	
  foreach i in $items[]
  {
  	string itemName = to_string(i);
  	string itemNum = to_int(i);
  	string loopNum = 1;
  	string line = loopNum + ":" + itemNum + ":" + itemName + "<br>";
  	
  	line = replace_string(line, ":", "_");

  	writeln(line) ;
  }
}

test-replace.ash:
Code:
void main()
{
	item i;
	
  foreach i in $locations[]
  {
  	foreach j in $locations[]
  	{
	  	string itemName = to_string(i);
	  	string itemNum = to_string(i);
	  	string loopNum = to_string(j);
	  	string line = itemName + ":" + itemNum + ":" + loopNum + "\n";
	  	
	  	line = replace_string(line, ":", "_");
	  	
	  	print(line);
	  }
  }
}

This results in occasional string corruption in both contexts:

In the character pane:
Code:
1_89_sword hilt
A Well-Groomed Lawn_A Well-Groomed Lawn_Barn 1_91_pants kit
1_92_meatsmithing guide
...
1_206_piercing post
A Well-Groomed Lawn_A Well-Groomed Lawn_Queen's Chamber 1_208_patchouli incense stick
...
1_979_tiny plastic grue
tiny plastic grue_A Well-Groomed Lawn_Fear Man's Level 1_981_tiny plastic ghuol whelp
1_982_tiny plastic baby gravy fairy

In the gCLI:
Code:
1_171_lihc eye pie<br>
A Well-Groomed Lawn_A Well-Groomed Lawn_Hatching Chamber
...
A Well-Groomed Lawn_A Well-Groomed Lawn_Dire Warren
dead guy's watch_A Well-Groomed Lawn_Orc Chasm
1_238_bottle of vodka<br>
A Well-Groomed Lawn_A Well-Groomed Lawn_Barrel full of Barrels
A Well-Groomed Lawn_A Well-Groomed Lawn_Nemesis Cave
A Well-Groomed Lawn_A Well-Groomed Lawn_Smut Orc Logging Camp
white lightning_A Well-Groomed Lawn_A-Boo Peak
A Well-Groomed Lawn_A Well-Groomed Lawn_Twin Peak
...
A Well-Groomed Lawn_A Well-Groomed Lawn_The Outer Compound
acoustic guitarrr_A Well-Groomed Lawn_The Temple Portico
A Well-Groomed Lawn_A Well-Groomed Lawn_Convention Hall Lobby
Ferrigno's Elixir of Power_A Well-Groomed Lawn_Outside the Club
A Well-Groomed Lawn_A Well-Groomed Lawn_The Barracks
...
A Well-Groomed Lawn_A Well-Groomed Lawn_Small-O-Fier
flaming crutch_A Well-Groomed Lawn_Huge-A-Ma-tron
A Well-Groomed Lawn_A Well-Groomed Lawn_Foyer
A Well-Groomed Lawn_A Well-Groomed Lawn_Chapel
A Well-Groomed Lawn_A Well-Groomed Lawn_Kegger in the Woods
spray paint_A Well-Groomed Lawn_Electric Lemonade Acid Parade
A Well-Groomed Lawn_A Well-Groomed Lawn_Neckback Crick
A Well-Groomed Lawn_A Well-Groomed Lawn_Trick-or-Treating
1_553_31337 scroll<br>
A Well-Groomed Lawn_A Well-Groomed Lawn_St. Sneaky Pete's Day Stupor
 

Attachments

  • charpane-replace.txt
    156.4 KB · Views: 2,786
  • gCLI-replace.txt
    31.8 KB · Views: 105

roippi

Developer
Eh, never mind. Don't know exactly where this is happening.

The fact that the same error happens in two distinct functions points to the problem lying not in either of those functions but rather in the two interpreters interfering with each other somehow. The fact that they are string-handling functions is likely coincidence in that they are both relatively expensive (and therefore long-running) computations. So far I haven't come up with a way two interpreters could be interfering with each other like this.
 

roippi

Developer
more debugging

normal execution of outer foreach loop in your GCLI script

Code:
            Key: Pump Up Mysticality

                  Eval: to_string()

                     Param #1: i

                     [NORMAL] <- "Pump Up Muscle"

                     Entering function to_string

                     Function to_string returned: Pump Up Muscle

                  Set: Pump Up Muscle

               [NORMAL] <- "Pump Up Muscle"

                  Eval: to_string()

                     Param #1: i

                     [NORMAL] <- "Pump Up Muscle"

                     Entering function to_string

                     Function to_string returned: Pump Up Muscle

                  Set: Pump Up Muscle

               [NORMAL] <- "Pump Up Muscle"

                  Eval: to_string()

                     Param #1: j

                     [NORMAL] <- "Pump Up Mysticality"

                     Entering function to_string

                     Function to_string returned: Pump Up Mysticality

                  Set: Pump Up Mysticality

               [NORMAL] <- "Pump Up Mysticality"

                  Eval: ( ( ( ( ( itemName + ":" ) + itemNum ) + ":" ) + loopNum ) + "
" )

                     Operator: +

                        Operand 1: ( ( ( ( itemName + ":" ) + itemNum ) + ":" ) + loopNum )

                           Operator: +

                              Operand 1: ( ( ( itemName + ":" ) + itemNum ) + ":" )

                                 Operator: +

                                    Operand 1: ( ( itemName + ":" ) + itemNum )

                                       Operator: +

                                          Operand 1: ( itemName + ":" )

                                             Operator: +

                                                Operand 1: itemName

                                                [NORMAL] <- "Pump Up Muscle"

                                                Operand 2: :

                                                [NORMAL] <- ":"

                                             <- Pump Up Muscle:

                                          [NORMAL] <- "Pump Up Muscle:"

                                          Operand 2: itemNum

                                          [NORMAL] <- "Pump Up Muscle"

                                       <- Pump Up Muscle:Pump Up Muscle

                                    [NORMAL] <- "Pump Up Muscle:Pump Up Muscle"

                                    Operand 2: :

                                    [NORMAL] <- ":"

                                 <- Pump Up Muscle:Pump Up Muscle:

                              [NORMAL] <- "Pump Up Muscle:Pump Up Muscle:"

                              Operand 2: loopNum

                              [NORMAL] <- "Pump Up Mysticality"

                           <- Pump Up Muscle:Pump Up Muscle:Pump Up Mysticality

                        [NORMAL] <- "Pump Up Muscle:Pump Up Muscle:Pump Up Mysticality"

                        Operand 2: 


                        [NORMAL] <- "
"

                     <- Pump Up Muscle:Pump Up Muscle:Pump Up Mysticality


                  Set: Pump Up Muscle:Pump Up Muscle:Pump Up Mysticality


               [NORMAL] <- "Pump Up Muscle:Pump Up Muscle:Pump Up Mysticality
"

                  Eval: replace_string()

                     Param #1: line

                     [NORMAL] <- "Pump Up Muscle:Pump Up Muscle:Pump Up Mysticality
"

                     Param #2: ":"

                     [NORMAL] <- ":"

                     Param #3: "_"

                     [NORMAL] <- "_"

                     Entering function replace_string

                     Function replace_string returned: Pump Up Muscle_Pump Up Muscle_Pump Up Mysticality


                  Set: Pump Up Muscle_Pump Up Muscle_Pump Up Mysticality


               [NORMAL] <- "Pump Up Muscle_Pump Up Muscle_Pump Up Mysticality
"

                  Param #1: line

                  [NORMAL] <- "Pump Up Muscle_Pump Up Muscle_Pump Up Mysticality
"

                  Entering function print

Pump Up Muscle_Pump Up Muscle_Pump Up Mysticality

                  Function print returned: void

               [NORMAL] <- void

interleaved execution

Code:
      Key: herbs

            Key: Battlefield (Frat Uniform)

                  Eval: to_string()

                     Param #1: i

                     [NORMAL] <- "Pump Up Moxie"

                     Entering function to_string

            Eval: to_string()

                     Function to_string returned: Pump Up Moxie

                  Set: Pump Up Moxie

               [NORMAL] <- "Pump Up Moxie"

                  Eval: to_string()

                     Param #1: i

                     [NORMAL] <- "Pump Up Moxie"

                     Entering function to_string

                     Function to_string returned: Pump Up Moxie

                  Set: Pump Up Moxie

               [NORMAL] <- "Pump Up Moxie"

                  Eval: to_string()

                     Param #1: j

                     [NORMAL] <- "Battlefield (Frat Uniform)"

                     Entering function to_string

                     Function to_string returned: Battlefield (Frat Uniform)

                  Set: Battlefield (Frat Uniform)

               [NORMAL] <- "Battlefield (Frat Uniform)"

               Param #1: i

               [NORMAL] <- "herbs"

               Entering function to_string

               Function to_string returned: herbs

            Set: herbs

         [NORMAL] <- "herbs"

            Eval: to_int()

               Param #1: i

               [NORMAL] <- "herbs"

               Entering function to_int

               Function to_int returned: 203

            Set: 203

         [NORMAL] <- "203"

            Eval: 1

            Set: 1

         [NORMAL] <- "1"

                  Eval: ( ( ( ( ( itemName + ":" ) + itemNum ) + ":" ) + loopNum ) + "
" )

                     Operator: +

            Eval: ( ( ( ( ( loopNum + ":" ) + itemNum ) + ":" ) + itemName ) + "<br>" )

               Operator: +

                        Operand 1: ( ( ( ( itemName + ":" ) + itemNum ) + ":" ) + loopNum )

                           Operator: +

                  Operand 1: ( ( ( ( loopNum + ":" ) + itemNum ) + ":" ) + itemName )

                     Operator: +

                              Operand 1: ( ( ( itemName + ":" ) + itemNum ) + ":" )

                                 Operator: +

                                    Operand 1: ( ( itemName + ":" ) + itemNum )

                                       Operator: +

                                          Operand 1: ( itemName + ":" )

                                             Operator: +

                                                Operand 1: itemName

                                                [NORMAL] <- "Pump Up Moxie"

                        Operand 1: ( ( ( loopNum + ":" ) + itemNum ) + ":" )

                           Operator: +

                              Operand 1: ( ( loopNum + ":" ) + itemNum )

                                 Operator: +

                                    Operand 1: ( loopNum + ":" )

                                       Operator: +

                                          Operand 1: loopNum

                                          [NORMAL] <- "1"

                                                Operand 2: :

                                                [NORMAL] <- ":"

                                          Operand 2: :

                                          [NORMAL] <- ":"

                                       <- 1:

                                    [NORMAL] <- "1:"

                                    Operand 2: itemNum

                                    [NORMAL] <- "203"

                                 <- 1:203

                              [NORMAL] <- "1:203"

                              Operand 2: :

                              [NORMAL] <- ":"

                           <- 1:203:

                        [NORMAL] <- "1:203:"

                        Operand 2: itemName

                        [NORMAL] <- "herbs"

                     <- 1:203:herbs

                  [NORMAL] <- "1:203:herbs"

                                             <- Pump Up Moxie:

                                          [NORMAL] <- "Pump Up Moxie:"

                  Operand 2: <br>

                  [NORMAL] <- "<br>"

               <- 1:203:herbs<br>

            Set: 1:203:herbs<br>

         [NORMAL] <- "1:203:herbs<br>"

            Eval: replace_string()

               Param #1: line

               [NORMAL] <- "1:203:herbs<br>"

               Param #2: ":"

               [NORMAL] <- ":"

               Param #3: "_"

               [NORMAL] <- "_"

               Entering function replace_string

                                          Operand 2: itemNum

                                          [NORMAL] <- "Pump Up Moxie"

                                       <- Pump Up Moxie:Pump Up Moxie

                                    [NORMAL] <- "Pump Up Moxie:Pump Up Moxie"

               Function replace_string returned: 1_203_herbs<br>

            Set: 1_203_herbs<br>

         [NORMAL] <- "1_203_herbs<br>"

            Param #1: line

            [NORMAL] <- "1_203_herbs<br>"

                                          Operand 2: :

                                    [NORMAL] <- ":"

                                 <- Pump Up Moxie:Pump Up Moxie:

                              [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:"

      Entering function writeln

                              Operand 2: loopNum

                              [NORMAL] <- "Battlefield (Frat Uniform)"

                           <- Pump Up Moxie:Pump Up Moxie:Battlefield (Frat Uniform)

                        [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Frat Uniform)"

                        Operand 2: 


                        [NORMAL] <- "
"

                     <- Pump Up Moxie:Pump Up Moxie:Battlefield (Frat Uniform)


                  Set: Pump Up Moxie:Pump Up Moxie:Battlefield (Frat Uniform)


               [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Frat Uniform)
"

                  Eval: replace_string()

                     Param #1: line

                     [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Frat Uniform)
"

                     Param #2: ":"

                     [NORMAL] <- ":"

                     Param #3: "_"

                     [NORMAL] <- "_"

                     Entering function replace_string

            Function writeln returned: void

         [NORMAL] <- void

                     Function replace_string returned: Pump Up Moxie_Pump Up Moxie_Battlefield (Frat Uniform)


                  Set: Pump Up Moxie_Pump Up Moxie_Battlefield (Frat Uniform)


               [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Frat Uniform)
"

                  Param #1: line

                  [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Frat Uniform)
"

                  Entering function print

      Key: carob chunk cookies

Pump Up Moxie_Pump Up Moxie_Battlefield (Frat Uniform)

            Eval: to_string()

                                 Function print returned: void

               [NORMAL] <- void

Param #1: i

               [NORMAL] <- "carob chunk cookies"

               Entering function to_string

            Key: Battlefield (Hippy Uniform)

                  Eval: to_string()

                     Param #1: i

                     [NORMAL] <- "Pump Up Moxie"

                     Entering function to_string

                     Function to_string returned: Pump Up Moxie

                  Set: Pump Up Moxie

               [NORMAL] <- "Pump Up Moxie"

                  Eval: to_string()

                     Param #1: i

                     [NORMAL] <- "Pump Up Moxie"

                     Entering function to_string

                     Function to_string returned: Pump Up Moxie

                  Set: Pump Up Moxie

               [NORMAL] <- "Pump Up Moxie"

                  Eval: to_string()

                     Param #1: j

                     [NORMAL] <- "Battlefield (Hippy Uniform)"

                     Entering function to_string

                     Function to_string returned: Battlefield (Hippy Uniform)

                  Set: Battlefield (Hippy Uniform)

               [NORMAL] <- "Battlefield (Hippy Uniform)"

               Function to_string returned: carob chunk cookies

            Set: carob chunk cookies

         [NORMAL] <- "carob chunk cookies"

            Eval: to_int()

               Param #1: i

               [NORMAL] <- "carob chunk cookies"

               Entering function to_int

                  Eval: ( ( ( ( ( itemName + ":" ) + itemNum ) + ":" ) + loopNum ) + "
" )

                     Operator: +

               Function to_int returned: 204

            Set: 204

         [NORMAL] <- "204"

            Eval: 1

            Set: 1

         [NORMAL] <- "1"

                        Operand 1: ( ( ( ( itemName + ":" ) + itemNum ) + ":" ) + loopNum )

                           Operator: +

            Eval: ( ( ( ( ( loopNum + ":" ) + itemNum ) + ":" ) + itemName ) + "<br>" )

               Operator: +

                              Operand 1: ( ( ( itemName + ":" ) + itemNum ) + ":" )

                                 Operator: +

                                    Operand 1: ( ( itemName + ":" ) + itemNum )

                                       Operator: +

                                          Operand 1: ( itemName + ":" )

                                             Operator: +

                                                Operand 1: itemName

                  Operand 1: ( ( ( ( loopNum + ":" ) + itemNum ) + ":" ) + itemName )

                     Operator: +

                                                [NORMAL] <- "Pump Up Moxie"

                        Operand 1: ( ( ( loopNum + ":" ) + itemNum ) + ":" )

                           Operator: +

                              Operand 1: ( ( loopNum + ":" ) + itemNum )

                                 Operator: +

                                    Operand 1: ( loopNum + ":" )

                                                               Operand 2: :

                                                [NORMAL] <- ":"

                                             <- Pump Up Moxie:

                                          [NORMAL] <- "Pump Up Moxie:"

                        Operator: +

                                          Operand 1: loopNum

                                          [NORMAL] <- "1"

                                          Operand 2: itemNum

                                          Operand 2: :

                                          [NORMAL] <- ":"

                                       <- 1:

                                    [NORMAL] <- "1:"

                                          [NORMAL] <- "Pump Up Moxie"

                                    Operand 2: itemNum

                                    [NORMAL] <- "204"

                                 <- 1:204

                              [NORMAL] <- "1:204"

                                       <- Pump Up Moxie:Pump Up Moxie

                                             Operand 2: :

                              [NORMAL] <- ":"

                           <- 1:204:

                        [NORMAL] <- "1:204:"

                     [NORMAL] <- "Pump Up Moxie:Pump Up Moxie"

                        Operand 2: itemName

                        [NORMAL] <- "carob chunk cookies"

                     <- 1:204:carob chunk cookies

                  [NORMAL] <- "1:204:carob chunk cookies"

                  Operand 2: <br>

                  [NORMAL] <- "<br>"

               <- 1:204:carob chunk cookies<br>

            Set: 1:204:carob chunk cookies<br>

                                    Operand 2: :

                                    [NORMAL] <- ":"

         [NORMAL] <- "1:204:carob chunk cookies<br>"

            Eval: replace_string()

                                 <- Pump Up Moxie:Pump Up Moxie:

                              [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:"

               Param #1: line

                              Operand 2: loopNum

                              [NORMAL] <- "Battlefield (Hippy Uniform)"

                           <- Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)

                        [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)"

               [NORMAL] <- "1:204:carob chunk cookies<br>"

               Param #2: ":"

               [NORMAL] <- ":"

               Param #3: "_"

               [NORMAL] <- "_"

                        Operand 2: 


                        [NORMAL] <- "
"

                     <- Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)


                  Set: Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)


               [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)
"

                  Eval: replace_string()

                     Param #1: line

                     [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)
"

                     Param #2: ":"

                     [NORMAL] <- ":"

                     Param #3: "_"

                     [NORMAL] <- "_"

                     Entering function replace_string

               Entering function replace_string

                     Function replace_string returned: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)


                  Set: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)


               [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)
"

                  Param #1: line

                  [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)
"

                  Entering function print

               Function replace_string returned: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)


            Set: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)


         [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)
"

            Param #1: line

            [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)
"

            Entering function writeln

Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)

            Function writeln returned: void

         [NORMAL] <- void

...

ends up with in charpane:

Code:
1_203_herbs
Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform) 1_205_secret blend of herbs and spices
1_206_piercing post

Trouble section:

PHP:
         [NORMAL] <- "1:204:carob chunk cookies<br>"

            Eval: replace_string()  //replace string 1

                                 <- Pump Up Moxie:Pump Up Moxie:

                              [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:"

               Param #1: line

                              Operand 2: loopNum

                              [NORMAL] <- "Battlefield (Hippy Uniform)"

                           <- Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)

                        [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)"

               [NORMAL] <- "1:204:carob chunk cookies<br>"

               Param #2: ":"

               [NORMAL] <- ":"

               Param #3: "_"

               [NORMAL] <- "_"

                        Operand 2: 


                        [NORMAL] <- "
"

                     <- Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)


                  Set: Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)


               [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)
"

                  Eval: replace_string() //replace string 2

                     Param #1: line

                     [NORMAL] <- "Pump Up Moxie:Pump Up Moxie:Battlefield (Hippy Uniform)
"

                     Param #2: ":"

                     [NORMAL] <- ":"

                     Param #3: "_"

                     [NORMAL] <- "_"

                     Entering function replace_string  //NOTE

               Entering function replace_string //NOTE

                     Function replace_string returned: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform) //BAD RETURN VALUE, SHOULD BE CAROB CHUNK COOKIES


                  Set: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)


               [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)
"

                  Param #1: line

                  [NORMAL] <- "Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform)
"

                  Entering function print

               Function replace_string returned: Pump Up Moxie_Pump Up Moxie_Battlefield (Hippy Uniform) //CORRECT RETURN VALUE

The debug output is confusing in that it was not designed to handle concurrent scripts running like this, so the indentation is routinely wrong and the two interpreters are nowhere near as interleaved as it appears in the output. Still, it's helpful. See the lines that I commented for signs of where the problem lies. The two interpreters are calling replace_string at the same time, and the return value from the second one is "overwriting" the first.

Here's the signature of replace_string:

Code:
public static Value replace_string( Interpreter interpreter, final Value source, final Value searchValue, final Value replaceValue )

Normally I can't see a problem with two threads calling this function simultaneously. Static methods are pretty much thread-safe unless they alter the state of some static fields, which this doesn't. My guess right now is that reflection is to blame. I know little about reflection, but that's how ASH functions are called, and I know that it can generate goofy problems. If two threads call this function via reflection, can they interfere with one another? I dunno. Outside of my expertise. More debugging will follow.
 

fronobulax

Developer
Staff member
more debugging

Thank you. Since I am not in a position to try and fix this myself, the next best thing is to look over your shoulder as you ponder it. Thanks for the details and the willingness to make informed speculation that might not be correct.
 

roippi

Developer
Thank you.

Yup. It's as much for me as anyone else since I really need to document complex stuff like this but I figured it would be of interest to others.

I inserted a debugging line at the first and last line of replace_string:

Code:
               Entering function replace_string

                     Entering function replace_string

source: Pump Up Mysticality:Pump Up Mysticality:Oil Peak //should be 1:24:ten-leaf clover<br>

source: Pump Up Mysticality:Pump Up Mysticality:Oil Peak

returning:Pump Up Mysticality_Pump Up Mysticality_Oil Peak

returning:Pump Up Mysticality_Pump Up Mysticality_Oil Peak

               Function replace_string returned: Pump Up Mysticality_Pump Up Mysticality_Oil Peak


                     Function replace_string returned: Pump Up Mysticality_Pump Up Mysticality_Oil Peak

So as I suspected, replace_string is being called simultaneously by two interpreters and the arguments of the second call are overwriting the first one. I suspect this can happen with any function in RuntimeLibrary.java.

A quick fix would be to synchronize this method and a few other expensive ones(so the second thread is blocked until the first thread finishes), but that would just be addressing the symptom.

AHA

Going down the rabbit hole led me to LibraryFunction.execute():

Code:
// Dereference variables and pass ScriptValues to function

		Iterator it = this.variableReferences.iterator();
		this.values[ 0 ] = interpreter;
		for ( int i = 1; it.hasNext(); ++i )
		{
			VariableReference current = (VariableReference) it.next();
			this.values[ i ] = current.getValue( interpreter ); //1
		}

		try
		{
			// Invoke the method
			return (Value) this.method.invoke( this, (Object []) this.values ); //2
		}

This is where the function gets called via reflection, at 2. Note how some static fields get set at 1. Now, imagine two threads simultaneously doing this, where one is at line 2 and the other is loading up the fields at line 1. There's your thread interference, courtesy of static fields, which so often are the culprit.

I'll have a fix for this later today (it's like ~5 lines of code really), I have to get back to work on some home improvement stuff I'm doing.
 

xKiv

Active member
So there's only one LibraryFunction object for each library function (understandable), and that one object is used by each function call (bug, because one object cannot hold parameters (this.variableReferences) for two (or more) different function calls at the same time)?
That probably calls for a separate FunctionCall objects, rather than "fixing it" in just LibraryFunction ...
 

roippi

Developer
So there's only one LibraryFunction object for each library function (understandable), and that one object is used by each function call (bug, because one object cannot hold parameters (this.variableReferences) for two (or more) different function calls at the same time)?
That probably calls for a separate FunctionCall objects, rather than "fixing it" in just LibraryFunction ...

You're close.

The issue is not that we can't spawn as many FunctionCall objects as we want (we can), but rather that FunctionCall.execute() does

Code:
				paramVarRef.setValue( interpreter, value );

before doing

Code:
				result = this.target.execute( interpreter );

In English: each LibraryFunction has a set of associated static fields. In order to run, FunctionCall first sets those fields, then executes the LibraryFunction. Associated problems arise when two threads try to do this at the exact same time.

What's bonkers is that this can occur for any LibraryFunction - including to_int, to_string, etc. The fact that those are superfast methods means that it's far less likely, but I'm sure it's happened to someone somewhere.

Right now I think I'm just going to throw a synchronization block around the part of FunctionCall that sets the fields and then executes the function. It won't block on different functions, just two threads that call the same one. This is not the most satisfying solution but refactoring this in an object-oriented fashion would be a near total-rewrite of this part of ASH, something I'm not up for. Perhaps a more elegant concurrency-handling scheme could involve the 1.5 Locks package, that could be something I'd look into.

Testing my current fix now, it seems to work okay with minimal performance hit.
 

xKiv

Active member
I think that it would be better to synchronize the whole method body - who knows, maybe Function.saveBindings and Function.restoreBindings will do something sometime? Or is it possible that the same UserDefinedFunction would be run from two threads at the same time (in which case you would be in danger of them overwriting each other's bindings)?
 

fronobulax

Developer
Staff member
I think that it would be better to synchronize the whole method body

As a philosophy I was always taught that synchronizing is expensive and that too much synchronizing can lead to starvation conditions so the preferred practice is almost always to synchronize the least amount of code possible which is almost never the entire method body.
 

xKiv

Active member
As a philosophy I was always taught that synchronizing is expensive and that too much synchronizing can lead to starvation conditions so the preferred practice is almost always to synchronize the least amount of code possible which is almost never the entire method body.

I was taught that it's always better to fix things before they break in production. In this case, it means synchronizing the entire method, because it's using the same instance of Function from the start to the end. Or better yet, rewrite so that you don't need synchronization - but roippi didn't want to change the code that much.
 

roippi

Developer
As a philosophy I was always taught that synchronizing is expensive and that too much synchronizing can lead to starvation conditions so the preferred practice is almost always to synchronize the least amount of code possible which is almost never the entire method body.

As a philosophy, I agree, which is why I was parsimonious with the first synch block. However, in this case xkiv is right in that UserDefinedFunctions were still able to do thread-unsafe things outside of the synchronization block. I didn't see it because UserDefinedFunctions override some inherited methods in order to do that stuff. Grumble.
 

Veracity

Developer
Staff member
Or is it possible that the same UserDefinedFunction would be run from two threads at the same time (in which case you would be in danger of them overwriting each other's bindings)?
UserDefinedFunctions are compiled fresh for each Interpreter, even if they are both from zlib, for example. If two threads are running the same Interpreter, we have a problem. We could synchronize on the interpreter object to prevent that.

In English: each LibraryFunction has a set of associated static fields. In order to run, FunctionCall first sets those fields, then executes the LibraryFunction. Associated problems arise when two threads try to do this at the exact same time.
What static fields? I see "method" and "values", but those are per-object, not static.

Now, RuntimeLibrary has a static list of functions, which means that all interpreters use the same LibraryFunction objects, as opposed to UserDefinedFunctions which are compiled fresh for each interpreter.

Hmm. Seems to me that if you change LibraryFunction.values from a per-object array into a normal variable within LibraryFunction.execute that different Interpreters executing the same Library function will no longer interfere with each other, obviating synchronization.

It was a long time ago, but I think we make values a per-object variable was so that we could allocate the array once, at object creation time, rather than each time the function was executed.

So, that is the trade-off: thread synchronization to keep two threads from being inside the same LibraryFunction (or any function, as currently coded, although it should not be possible with UserDefinedFunctions) vs. doing "values = new Object[ params.length + 1];" in LibraryFunction.execute rather than in the constructor.
 

roippi

Developer
What static fields? I see "method" and "values", but those are per-object, not static.

I misspoke, or was speaking in the abstract perhaps. The variableReference fields are not actually static, LibraryFunction objects are shared in a static way as you say.

UserDefinedFunctions are compiled fresh for each Interpreter, even if they are both from zlib, for example.

Didn't think of that. We can probably revert r12011, then.

Hmm. Seems to me that if you change LibraryFunction.values from a per-object array into a normal variable within LibraryFunction.execute that different Interpreters executing the same Library function will no longer interfere with each other, obviating synchronization.

...

So, that is the trade-off: thread synchronization to keep two threads from being inside the same LibraryFunction (or any function, as currently coded, although it should not be possible with UserDefinedFunctions) vs. doing "values = new Object[ params.length + 1];" in LibraryFunction.execute rather than in the constructor.

I personally think the current solution is better than the alternative of allocating more heap space every time the function is called. Two threads calling a given function simultaneously is a very, very rare event, so the performance cost here seems minimal.
 

xKiv

Active member
So, that is the trade-off: thread synchronization to keep two threads from being inside the same LibraryFunction (or any function, as currently coded, although it should not be possible with UserDefinedFunctions) vs. doing "values = new Object[ params.length + 1];" in LibraryFunction.execute rather than in the constructor.

Another point in the trade-off is that, if you keep the arrays forever-allocated, they will *always* be allocated, even when they are not needed. That's not really recommended. Probably because it makes them move from eden to old generation, and has a performance hit on every GC from then on. That hit is probably very small here, but add to it the hit of synchronization on each call of a library function ... versus the performance hit of allocating an array per call, but in eden, which is optimized for quick allocations of short-lived objects. It will probably depend on how long-lived the function call is, in terms of allocated memory, but I am not a living performance profiler, so my thought will have to stop at "I don't know".

roippi said:
Two threads calling a given function simultaneously is a very, very rare event, so the performance cost here seems minimal.

The performance hit happens even if only one thread calls the function. That's why you don't pre-emptively synchronize everything, after all.
 

Veracity

Developer
Staff member
The performance hit happens even if only one thread calls the function. That's why you don't pre-emptively synchronize everything, after all.
Agreed. I prefer allocating the values array only when necessary and letting the GC do its thing efficiently, which makes LibraryFunction thread safe and makes synchronizing FunctionCall unnecessary.

Revision 12015.
 

roippi

Developer
r12015 re-introduces the bug.

Code:
1_355_eXtreme scarf
Whitey's Grove_Whitey's Grove_Barrrney's Barrr 1_357_Mountain Stream soda

Doing Object[] values = new Object[ this.paramCount + 1]; does not make LibraryFunction thread-safe. The leak is not there, but at

Code:
		Iterator it = this.variableReferences.iterator();

This is because two threads at the same time are able to execute this block in FunctionCall:

Code:
		Iterator refIterator = this.target.getReferences();
		paramCount = 0;
		while ( refIterator.hasNext() )
		{
			VariableReference paramVarRef = (VariableReference) refIterator.next();
			Value value = values[ paramCount ];
			++paramCount;

			// Bind parameter to new value
			paramVarRef.setValue( interpreter, value ); // RACE CONDITION
		}

I perhaps should have explained this better when I committed it. What Veracity committed would have fixed the race condition I mentioned in post #8, but the overriding one is the one in post #10. I think the one in post #8 does actually exist, but it happens maybe 1/1000th the frequency of the one from post #10.
 
Last edited:
Top