Results not output in execution time order? [question]

[pbowyer]

Thanks for writing this library Kris. I have a question: for the code samples below (doing the same thing in two different ways) why does the output appear in the order of the input, not in the order the processes finished? Can I change that?

I'm trying to speed up calling webservices by calling them in parallel and returning results to the client (via HTTP) as quickly as possible. Running them in parallel and getting all results back at once is an improvement over the current serial pipeline, but I don't understand why they're not in order of execution time?

<?php
/*
Outputs:
[PID 5162] This should appear Third | 3.000156879425 | 3.0109901428223
[PID 5163] This should appear Fourth | 5.0002059936523 | 5.0195519924164
[PID 5164] This should appear First | 3.9815902709961E-5 | 0.024851083755493
[PID 5165] This should appear Second | 1.0001690387726 | 1.031200170517
*/
require 'vendor/autoload.php';

$manager = new Spork\ProcessManager(new \Spork\EventDispatcher\EventDispatcher(), true);
$t = microtime(true);

$x = array(array('Third', 3), array('Fourth', 5), array('First', 0), array('Second', 1));

foreach ($x as $result) {
    $callback = function() use($result, $t) {
        $t1 = microtime(true);
        sleep($result[1]);
        return '[PID '. getmypid() .'] This should appear '.$result[0] ." | " . (microtime(true) - $t1) ." | " . (microtime(true) - $t);
    };

    $manager->fork($callback)
      ->then(function(Spork\Fork $fork) use ($t) {
              // This returns the result from ALL forks. I want to return it for each for when it completes
              echo $fork->getResult() ."\n";
              // do something in the parent process when it's done!
              #echo "{$fork->getPid()} says '{$fork->getResult()}'\n";
              flush();
          });
}

or

<?php
/*
Outputs:
array(4) {
  [0]=>
  string(52) "[PID 5169] This should appear Third | 3.022490978241"
  [1]=>
  string(54) "[PID 5170] This should appear Fourth | 5.0275919437408"
  [2]=>
  string(55) "[PID 5171] This should appear First | 0.031582117080688"
  [3]=>
  string(54) "[PID 5172] This should appear Second | 1.0402359962463"
}
5.0930731296539
*/
require 'vendor/autoload.php';

$strategy = new \Spork\Batch\Strategy\ChunkStrategy(4);
$manager = new Spork\ProcessManager(new \Spork\EventDispatcher\EventDispatcher(), true);
$t = microtime(true);

$callback = function($result) use($t) {
    #$result = current($result);
    sleep($result[1]);
    return '[PID '. getmypid() .'] This should appear '.$result[0] ." | " . (microtime(true) - $t);
};

$manager->process(array(array('Third', 3), array('Fourth', 5), array('First', 0), array('Second', 1)), $callback, $strategy)
    ->then(function(Spork\Fork $fork) use ($t) {
          // This returns the result from ALL forks. I want to return it for each for when it completes
          var_dump($fork->getResult());
          echo (microtime(true) - $t)  ."\n";
      });

[seyfer]

Maybe because in multy thread mode there no order for running process? They complete in parallel, not one by one.

[djsharman]

Ditto the above results.

use BR_MODS\Logger;
use Evenement\EventEmitterInterface;
use Evenement\EventEmitterTrait;
use Spork\Fork;
use Spork\ProcessManager;

class ThreadTest implements EventEmitterInterface{

    /**
     * Implements EventEmitterInterface
     *
     * @uses \Evenement\EventEmitterTrait
     */
    use EventEmitterTrait;


    public function __construct() {


        $this->count = 0;

        $this->on('log', function($log_msg) {
            Logger::info(null, $log_msg);
        });


    }


    public function doWork( ProcessManager $manager, $i) {

            $curTime = microtime(true);
            Logger::info(null, "Starting: $i");

            $fork_deferred = $manager->fork(function( \Spork\SharedMemory $sharedMemory) use ($i, $curTime)  {

                Logger::info(null, 'Greeting from '.$i. ' : '. getmypid());
                $rand2 = rand(1, 5);
                if($i == 4) {
                    $rand2 = 9;
                }

                sleep ( $rand2);

                $time_diff = round(microtime(true) - $curTime,3);


                Logger::info(null, 'Finished from '.$i. ' : '. getmypid());

                $res = 'Hello from '.getmypid() . ' with $i: '.$i. ' and $rand2 '. $rand2. ' finish Time: '. date("h:i:s") . ' diff time: '. $time_diff ;

                return $res;

                }
            );

            return $fork_deferred;
    }

    public function go() {


        $manager = new ProcessManager(null, null, true);



        for($i=1;$i<=15;$i++){

            $fork_deferred = $this->doWork($manager, $i);



            $fork_deferred->then(function ( Fork $fork) use ($i) {
                $res = $fork->getResult();
                $this->emit('log', array("Done: $res"));

            });

        }

    }

}


$time_start = microtime(true);

$Thread = new ThreadTest();
$Thread->go();

//\BR_MODS\LoopMgrModel::run();

$time_end = microtime(true);

$execution_time = ($time_end - $time_start);
echo 'Total Execution Time: '.$execution_time.' Seconds'. "\n";

output is as follows

2015-09-19T13:31:21.7626200 info Starting: 1
2015-09-19T13:31:21.7856890 info Greeting from 1 : 14471
2015-09-19T13:31:21.8012250 info Starting: 2
2015-09-19T13:31:21.8021390 info Starting: 3
2015-09-19T13:31:21.8030600 info Starting: 4
2015-09-19T13:31:21.8038230 info Starting: 5
2015-09-19T13:31:21.8046540 info Starting: 6
2015-09-19T13:31:21.8055780 info Starting: 7
2015-09-19T13:31:21.8069550 info Starting: 8
2015-09-19T13:31:21.8081700 info Starting: 9
2015-09-19T13:31:21.8109340 info Starting: 10
2015-09-19T13:31:21.8139750 info Starting: 11
2015-09-19T13:31:21.8166160 info Starting: 12
2015-09-19T13:31:21.8213780 info Starting: 13
2015-09-19T13:31:21.8249170 info Starting: 14
2015-09-19T13:31:21.8264450 info Starting: 15
2015-09-19T13:31:21.8452050 info Greeting from 3 : 14473
2015-09-19T13:31:21.8462180 info Greeting from 2 : 14472
2015-09-19T13:31:21.8831960 info Greeting from 7 : 14477
2015-09-19T13:31:21.8864440 info Greeting from 5 : 14475
2015-09-19T13:31:21.8880390 info Greeting from 8 : 14478
2015-09-19T13:31:21.8906100 info Greeting from 6 : 14476
2015-09-19T13:31:21.8918270 info Greeting from 9 : 14479
2015-09-19T13:31:21.8931900 info Greeting from 4 : 14474
2015-09-19T13:31:21.8936490 info Greeting from 11 : 14481
2015-09-19T13:31:21.8940820 info Greeting from 10 : 14480
2015-09-19T13:31:21.8942340 info Greeting from 12 : 14482
2015-09-19T13:31:21.8971060 info Greeting from 15 : 14485
2015-09-19T13:31:21.8985200 info Greeting from 13 : 14483
2015-09-19T13:31:21.8985200 info Greeting from 14 : 14484
2015-09-19T13:31:22.8925420 info Finished from 9 : 14479
2015-09-19T13:31:22.8966600 info Finished from 12 : 14482
2015-09-19T13:31:22.8991840 info Finished from 14 : 14484
2015-09-19T13:31:23.8871870 info Finished from 5 : 14475
2015-09-19T13:31:23.8956380 info Finished from 11 : 14481
2015-09-19T13:31:23.8979440 info Finished from 15 : 14485
2015-09-19T13:31:24.8463840 info Finished from 3 : 14473
2015-09-19T13:31:24.8474640 info Finished from 2 : 14472
2015-09-19T13:31:24.8968420 info Finished from 10 : 14480
2015-09-19T13:31:25.7884920 info Finished from 1 : 14471
2015-09-19T13:31:25.8023630 info Done: Hello from 14471 with $i: 1 and $rand2 4 finish Time: 01:31:25 diff time: 4.045
2015-09-19T13:31:25.8025760 info Done: Hello from 14472 with $i: 2 and $rand2 3 finish Time: 01:31:24 diff time: 3.046
2015-09-19T13:31:25.8027580 info Done: Hello from 14473 with $i: 3 and $rand2 3 finish Time: 01:31:24 diff time: 3.044
2015-09-19T13:31:25.8900300 info Finished from 8 : 14478
2015-09-19T13:31:26.8836060 info Finished from 7 : 14477
2015-09-19T13:31:26.8909600 info Finished from 6 : 14476
2015-09-19T13:31:26.8999900 info Finished from 13 : 14483
2015-09-19T13:31:30.8957060 info Finished from 4 : 14474
2015-09-19T13:31:30.9036370 info Done: Hello from 14474 with $i: 4 and $rand2 9 finish Time: 01:31:30 diff time: 9.093
2015-09-19T13:31:30.9038400 info Done: Hello from 14475 with $i: 5 and $rand2 2 finish Time: 01:31:23 diff time: 2.083
2015-09-19T13:31:30.9041370 info Done: Hello from 14476 with $i: 6 and $rand2 5 finish Time: 01:31:26 diff time: 5.086
2015-09-19T13:31:30.9042880 info Done: Hello from 14477 with $i: 7 and $rand2 5 finish Time: 01:31:26 diff time: 5.078
2015-09-19T13:31:30.9045110 info Done: Hello from 14478 with $i: 8 and $rand2 4 finish Time: 01:31:25 diff time: 4.083
2015-09-19T13:31:30.9046720 info Done: Hello from 14479 with $i: 9 and $rand2 1 finish Time: 01:31:22 diff time: 1.084
2015-09-19T13:31:30.9049120 info Done: Hello from 14480 with $i: 10 and $rand2 3 finish Time: 01:31:24 diff time: 3.086
2015-09-19T13:31:30.9051830 info Done: Hello from 14481 with $i: 11 and $rand2 2 finish Time: 01:31:23 diff time: 2.083
2015-09-19T13:31:30.9053330 info Done: Hello from 14482 with $i: 12 and $rand2 1 finish Time: 01:31:22 diff time: 1.08
2015-09-19T13:31:30.9057570 info Done: Hello from 14483 with $i: 13 and $rand2 5 finish Time: 01:31:26 diff time: 5.079
2015-09-19T13:31:30.9060220 info Done: Hello from 14484 with $i: 14 and $rand2 1 finish Time: 01:31:22 diff time: 1.074
2015-09-19T13:31:30.9061960 info Done: Hello from 14485 with $i: 15 and $rand2 2 finish Time: 01:31:23 diff time: 2.071
Total Execution Time: 9.1863651275635 Seconds

Threads all terminate in the order one would expect, but the final output arrives in the order in which the threads were started. Can anyone explain this result and how to get

->then(

to fire as a thread ends?

pbowyer, did you get to the bottom of this?

Regards,

Darren