I think Silvia had in mind parsing the timestamps etc. for the intermediate
plans in iterative search, as well. I can explain on Monday.

For the moment I have changed the program and let it parse now for the 
following string:

eval.add_pattern('search_time', r'^Search time: (.+)s', type=float, 
required=False, flags='MI')

This only makes sense for non-iterative results, right? I have not 
really understood how you want to handle the iterative results. You 
could explain it here or we could talk about that on Monday.

I looked into this and merged the C++ part.

Some notes:

1) The iterated search used to duplicate the already printed statistics after
everything has completed ("phase_statistics"). All this information was already
printed before, and I think it's not very useful since it's only printed when
iterated search completes, which usually means exhausting the search space. So
I've removed this.

2) The algorithm already printed the "Actual search time" for each plan (right
before printing the plan). This is not quite the same as the current timestamp,
but the info that Silvia is looking for can almost be reconstructed from this.
It's not terribly convenient, though, so I've added the current timestamp to
that "Actual search time" line.

3) I've implemented and merged the C++ part of this. Jendrik, can you extend the
scripts? For all the things that are printed for each solution, it would be good
to generate a list of results (e.g. list of expansions, plan costs, timestamps
for finding the solution, etc.) in addition to the "main" data point.

If you need a sample log file, the following call generates six solutions very
quickly on my machine:

X=21
cp ../../benchmarks/woodworking-sat08-strips/p$X-domain.pddl domain.pddl
cp ../../benchmarks/woodworking-sat08-strips/p$X.pddl problem.pddl
../translate/translate.py domain.pddl problem.pddl
../preprocess/preprocess < output.sas
./downward-1-debug < output --heuristic 'h=ff(cost_type=1)' \
   --search 'iterated(lazy_greedy(h, preferred=(h)), repeat_last=true)'

Here's what you get by grepping the log for "Actual search time":

Actual search time: 0s [t=0s]
Actual search time: 0s [t=0s]
Actual search time: 0.01s [t=0.01s]
Actual search time: 0s [t=0.01s]
Actual search time: 0.01s [t=0.02s]
Actual search time: 0s [t=0.02s]
Actual search time: 0.02s [t=0.04s]
Actual search time: 0.04s [t=0.04s]

For each row, the first time given is the time for computing that particular
solution, and the t=XXX info is the current timestamp (in keeping with the
conventions elsewhere in the code). Don't be confused by the last line saying
"Actual search time: 0.04s again" -- this is the total time for the iterated
search as a whole, so it is *not* added to the previous times. (This may be
confusing; I hope you can follow.) Jendrik, you can distinguish these overall
statistics from the single-search statistics by checking that it appears after a
line that says either "Solution found - stop searching" or "No solution found -
stop searching". Well, at least in most configs -- if repeat_last=false, it
might not be, but we don't use that config currently.

Nosying Jendrik because this will effect the results scripts.

It would be good if the iterative search printed out the current time stamp
every time a solution is found, as in the old LAMA. At the moment, search time
is only printed if the last iteration finishes, i.e. if the search space is
completely explored. (If the last iteration is aborted due to timeout, no search
time is ever printed to the log.)