00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
00016
00017
00018
00019
00020
00021
00022
00023
00024
00025
00026
00027
00028
00029
00030
00031
00032
00033
00034
00035
00036
00037 #include "ompl/tools/benchmark/Benchmark.h"
00038 #include "ompl/tools/benchmark/MachineSpecs.h"
00039 #include "ompl/util/Time.h"
00040 #include <boost/scoped_ptr.hpp>
00041 #include <boost/lexical_cast.hpp>
00042 #include <boost/progress.hpp>
00043 #include <fstream>
00044 #include <sstream>
00045
00047 namespace ompl
00048 {
00049 namespace tools
00050 {
00052 static std::string getResultsFilename(const Benchmark::CompleteExperiment &exp)
00053 {
00054 return "ompl_" + exp.host + "_" + boost::posix_time::to_iso_extended_string(exp.startTime) + ".log";
00055 }
00056
00058 static std::string getConsoleFilename(const Benchmark::CompleteExperiment &exp)
00059 {
00060 return "ompl_" + exp.host + "_" + boost::posix_time::to_iso_extended_string(exp.startTime) + ".console";
00061 }
00062
00063 static bool terminationCondition(const machine::MemUsage_t maxMem, const time::point &endTime)
00064 {
00065 if (time::now() < endTime && machine::getProcessMemoryUsage() < maxMem)
00066 return false;
00067 return true;
00068 }
00069
00070 class RunPlanner
00071 {
00072 public:
00073
00074 RunPlanner(const Benchmark *benchmark, bool useThreads)
00075 : benchmark_(benchmark), timeUsed_(0.0), memUsed_(0), crashed_(false), useThreads_(useThreads)
00076 {
00077 }
00078
00079 void run(const base::PlannerPtr &planner, const machine::MemUsage_t memStart, const machine::MemUsage_t maxMem, const double maxTime)
00080 {
00081 if (!useThreads_)
00082 {
00083 runThread(planner, memStart + maxMem, time::seconds(maxTime));
00084 return;
00085 }
00086
00087 boost::thread t(boost::bind(&RunPlanner::runThread, this, planner, memStart + maxMem, time::seconds(maxTime)));
00088
00089
00090 if (!t.timed_join(time::seconds(maxTime * 1.25)))
00091 {
00092 crashed_ = true;
00093
00094 std::stringstream es;
00095 es << "Planner " << benchmark_->getStatus().activePlanner << " did not complete run " << benchmark_->getStatus().activeRun
00096 << " within the specified amount of time (possible crash). Attempting to force termination of planning thread ..." << std::endl;
00097 std::cerr << es.str();
00098 msg_.error(es.str());
00099
00100 t.interrupt();
00101 t.join();
00102
00103 std::string m = "Planning thread cancelled";
00104 std::cerr << m << std::endl;
00105 msg_.error(m);
00106 }
00107
00108 if (memStart < memUsed_)
00109 memUsed_ -= memStart;
00110 else
00111 memUsed_ = 0;
00112 }
00113
00114 double getTimeUsed(void) const
00115 {
00116 return timeUsed_;
00117 }
00118
00119 machine::MemUsage_t getMemUsed(void) const
00120 {
00121 return memUsed_;
00122 }
00123
00124 bool crashed(void) const
00125 {
00126 return crashed_;
00127 }
00128
00129 private:
00130
00131 void runThread(const base::PlannerPtr &planner, const machine::MemUsage_t maxMem, const time::duration &maxDuration)
00132 {
00133 time::point timeStart = time::now();
00134
00135 try
00136 {
00137 base::PlannerTerminationConditionFn ptc = boost::bind(&terminationCondition, maxMem, time::now() + maxDuration);
00138 planner->solve(ptc, 0.1);
00139 }
00140 catch(std::runtime_error &e)
00141 {
00142 std::stringstream es;
00143 es << "There was an error executing planner " << benchmark_->getStatus().activePlanner << ", run = " << benchmark_->getStatus().activeRun << std::endl;
00144 es << "*** " << e.what() << std::endl;
00145 std::cerr << es.str();
00146 msg_.error(es.str());
00147 }
00148
00149 timeUsed_ = time::seconds(time::now() - timeStart);
00150 memUsed_ = machine::getProcessMemoryUsage();
00151 }
00152
00153 const Benchmark *benchmark_;
00154 double timeUsed_;
00155 machine::MemUsage_t memUsed_;
00156 bool crashed_;
00157 bool useThreads_;
00158 msg::Interface msg_;
00159 };
00160
00161 }
00162 }
00164
00165 bool ompl::tools::Benchmark::saveResultsToFile(const char *filename) const
00166 {
00167 bool result = false;
00168
00169 std::ofstream fout(filename);
00170 if (fout.good())
00171 {
00172 result = saveResultsToStream(fout);
00173 msg_.inform("Results saved to '%s'", filename);
00174 }
00175 else
00176 {
00177
00178 if (getResultsFilename(exp_) != std::string(filename))
00179 result = saveResultsToFile();
00180
00181 msg_.error("Unable to write results to '%s'", filename);
00182 }
00183 return result;
00184 }
00185
00186 bool ompl::tools::Benchmark::saveResultsToFile(void) const
00187 {
00188 std::string filename = getResultsFilename(exp_);
00189 return saveResultsToFile(filename.c_str());
00190 }
00191
00192 bool ompl::tools::Benchmark::saveResultsToStream(std::ostream &out) const
00193 {
00194 if (exp_.planners.empty())
00195 {
00196 msg_.warn("There is no experimental data to save");
00197 return false;
00198 }
00199
00200 if (!out.good())
00201 {
00202 msg_.error("Unable to write to stream");
00203 return false;
00204 }
00205
00206 out << "Experiment " << (exp_.name.empty() ? "NO_NAME" : exp_.name) << std::endl;
00207 out << "Running on " << (exp_.host.empty() ? "UNKNOWN" : exp_.host) << std::endl;
00208 out << "Starting at " << boost::posix_time::to_iso_extended_string(exp_.startTime) << std::endl;
00209 out << "<<<|" << std::endl << exp_.setupInfo << "|>>>" << std::endl;
00210
00211 out << exp_.seed << " is the random seed" << std::endl;
00212 out << exp_.maxTime << " seconds per run" << std::endl;
00213 out << exp_.maxMem << " MB per run" << std::endl;
00214 out << exp_.runCount << " runs per planner" << std::endl;
00215 out << exp_.totalDuration << " seconds spent to collect the data" << std::endl;
00216 out << exp_.planners.size() << " planners" << std::endl;
00217
00218 for (unsigned int i = 0 ; i < exp_.planners.size() ; ++i)
00219 {
00220 out << exp_.planners[i].name << std::endl;
00221
00222
00223 std::vector<std::string> properties;
00224 for (std::map<std::string, std::string>::const_iterator mit = exp_.planners[i].common.begin() ;
00225 mit != exp_.planners[i].common.end() ; ++mit)
00226 properties.push_back(mit->first);
00227 std::sort(properties.begin(), properties.end());
00228
00229
00230 out << properties.size() << " common properties" << std::endl;
00231 for (unsigned int k = 0 ; k < properties.size() ; ++k)
00232 {
00233 std::map<std::string, std::string>::const_iterator it = exp_.planners[i].common.find(properties[k]);
00234 out << it->first << " = " << it->second << std::endl;
00235 }
00236
00237
00238 std::map<std::string, bool> propSeen;
00239 for (unsigned int j = 0 ; j < exp_.planners[i].runs.size() ; ++j)
00240 for (std::map<std::string, std::string>::const_iterator mit = exp_.planners[i].runs[j].begin() ;
00241 mit != exp_.planners[i].runs[j].end() ; ++mit)
00242 propSeen[mit->first] = true;
00243
00244 properties.clear();
00245
00246 for (std::map<std::string, bool>::iterator it = propSeen.begin() ; it != propSeen.end() ; ++it)
00247 properties.push_back(it->first);
00248 std::sort(properties.begin(), properties.end());
00249
00250
00251 out << properties.size() << " properties for each run" << std::endl;
00252 for (unsigned int j = 0 ; j < properties.size() ; ++j)
00253 out << properties[j] << std::endl;
00254
00255
00256 out << exp_.planners[i].runs.size() << " runs" << std::endl;
00257 for (unsigned int j = 0 ; j < exp_.planners[i].runs.size() ; ++j)
00258 {
00259 for (unsigned int k = 0 ; k < properties.size() ; ++k)
00260 {
00261 std::map<std::string, std::string>::const_iterator it = exp_.planners[i].runs[j].find(properties[k]);
00262 if (it != exp_.planners[i].runs[j].end())
00263 out << it->second;
00264 out << "; ";
00265 }
00266 out << std::endl;
00267 }
00268
00269 out << '.' << std::endl;
00270 }
00271 return true;
00272 }
00273
00274 void ompl::tools::Benchmark::benchmark(const Request &req)
00275 {
00276
00277 if (gsetup_)
00278 {
00279 if (!gsetup_->getSpaceInformation()->isSetup())
00280 gsetup_->getSpaceInformation()->setup();
00281 }
00282 else
00283 {
00284 if (!csetup_->getSpaceInformation()->isSetup())
00285 csetup_->getSpaceInformation()->setup();
00286 }
00287
00288 if (!(gsetup_ ? gsetup_->getGoal() : csetup_->getGoal()))
00289 {
00290 msg_.error("No goal defined");
00291 return;
00292 }
00293
00294 if (planners_.empty())
00295 {
00296 msg_.error("There are no planners to benchmark");
00297 return;
00298 }
00299
00300 status_.running = true;
00301 exp_.totalDuration = 0.0;
00302 exp_.maxTime = req.maxTime;
00303 exp_.maxMem = req.maxMem;
00304 exp_.runCount = req.runCount;
00305 exp_.host = machine::getHostname();
00306 exp_.seed = RNG::getSeed();
00307
00308 exp_.startTime = time::now();
00309
00310 msg_.inform("Configuring planners ...");
00311
00312
00313 exp_.planners.clear();
00314 exp_.planners.resize(planners_.size());
00315
00316 const base::ProblemDefinitionPtr &pdef = gsetup_ ? gsetup_->getProblemDefinition() : csetup_->getProblemDefinition();
00317
00318 for (unsigned int i = 0 ; i < planners_.size() ; ++i)
00319 {
00320
00321 planners_[i]->setProblemDefinition(pdef);
00322 if (!planners_[i]->isSetup())
00323 planners_[i]->setup();
00324 exp_.planners[i].name = (gsetup_ ? "geometric_" : "control_") + planners_[i]->getName();
00325 msg_.inform("Configured " + exp_.planners[i].name);
00326 }
00327
00328 msg_.inform("Done configuring planners.");
00329 msg_.inform("Saving planner setup information ...");
00330
00331 std::stringstream setupInfo;
00332 if (gsetup_)
00333 gsetup_->print(setupInfo);
00334 else
00335 csetup_->print(setupInfo);
00336 setupInfo << std::endl << "Properties of benchmarked planners:" << std::endl;
00337 for (unsigned int i = 0 ; i < planners_.size() ; ++i)
00338 planners_[i]->printProperties(setupInfo);
00339 exp_.setupInfo = setupInfo.str();
00340
00341 msg_.inform("Done saving information");
00342
00343 msg_.inform("Beginning benchmark");
00344 msg::OutputHandler *oh = msg::getOutputHandler();
00345 boost::scoped_ptr<msg::OutputHandlerFile> ohf;
00346 if (req.saveConsoleOutput)
00347 {
00348 ohf.reset(new msg::OutputHandlerFile(getConsoleFilename(exp_).c_str()));
00349 msg::useOutputHandler(ohf.get());
00350 }
00351 else
00352 msg::noOutputHandler();
00353 msg_.inform("Beginning benchmark");
00354
00355 boost::scoped_ptr<boost::progress_display> progress;
00356 if (req.displayProgress)
00357 {
00358 std::cout << "Running experiment " << exp_.name << "." << std::endl;
00359 std::cout << "Each planner will be executed " << req.runCount << " times for at most " << req.maxTime << " seconds. Memory is limited at "
00360 << req.maxMem << "MB." << std::endl;
00361 progress.reset(new boost::progress_display(100, std::cout));
00362 }
00363
00364 machine::MemUsage_t memStart = machine::getProcessMemoryUsage();
00365 machine::MemUsage_t maxMemBytes = (machine::MemUsage_t)(req.maxMem * 1024 * 1024);
00366
00367 for (unsigned int i = 0 ; i < planners_.size() ; ++i)
00368 {
00369 status_.activePlanner = exp_.planners[i].name;
00370
00371 try
00372 {
00373 if (plannerSwitch_)
00374 {
00375 msg_.inform("Executing planner-switch event for planner %s ...", status_.activePlanner.c_str());
00376 plannerSwitch_(planners_[i]);
00377 msg_.inform("Completed execution of planner-switch event");
00378 }
00379 }
00380 catch(std::runtime_error &e)
00381 {
00382 std::stringstream es;
00383 es << "There was an error executing the planner-switch event for planner " << status_.activePlanner << std::endl;
00384 es << "*** " << e.what() << std::endl;
00385 std::cerr << es.str();
00386 msg_.error(es.str());
00387 }
00388 if (gsetup_)
00389 gsetup_->setup();
00390 else
00391 csetup_->setup();
00392 planners_[i]->params().getParams(exp_.planners[i].common);
00393 planners_[i]->getSpaceInformation()->params().getParams(exp_.planners[i].common);
00394
00395
00396 for (unsigned int j = 0 ; j < req.runCount ; ++j)
00397 {
00398 status_.activeRun = j;
00399 status_.progressPercentage = (double)(100 * (req.runCount * i + j)) / (double)(planners_.size() * req.runCount);
00400
00401 if (req.displayProgress)
00402 while (status_.progressPercentage > progress->count())
00403 ++(*progress);
00404
00405 msg_.inform("Preparing for run %d of %s", status_.activeRun, status_.activePlanner.c_str());
00406
00407
00408 try
00409 {
00410 planners_[i]->clear();
00411 if (gsetup_)
00412 {
00413 gsetup_->getGoal()->clearSolutionPaths();
00414 gsetup_->getSpaceInformation()->getMotionValidator()->resetMotionCounter();
00415 }
00416 else
00417 {
00418 csetup_->getGoal()->clearSolutionPaths();
00419 csetup_->getSpaceInformation()->getMotionValidator()->resetMotionCounter();
00420 }
00421 }
00422 catch(std::runtime_error &e)
00423 {
00424 std::stringstream es;
00425 es << "There was an error while preparing for run " << status_.activeRun << " of planner " << status_.activePlanner << std::endl;
00426 es << "*** " << e.what() << std::endl;
00427 std::cerr << es.str();
00428 msg_.error(es.str());
00429 }
00430
00431
00432 try
00433 {
00434 if (preRun_)
00435 {
00436 msg_.inform("Executing pre-run event for run %d of planner %s ...", status_.activeRun, status_.activePlanner.c_str());
00437 preRun_(planners_[i]);
00438 msg_.inform("Completed execution of pre-run event");
00439 }
00440 }
00441 catch(std::runtime_error &e)
00442 {
00443 std::stringstream es;
00444 es << "There was an error executing the pre-run event for run " << status_.activeRun << " of planner " << status_.activePlanner << std::endl;
00445 es << "*** " << e.what() << std::endl;
00446 std::cerr << es.str();
00447 msg_.error(es.str());
00448 }
00449
00450 RunPlanner rp(this, req.useThreads);
00451 rp.run(planners_[i], memStart, maxMemBytes, req.maxTime);
00452 bool solved = gsetup_ ? gsetup_->haveSolutionPath() : csetup_->haveSolutionPath();
00453
00454
00455 try
00456 {
00457 RunProperties run;
00458
00459 run["crashed BOOLEAN"] = boost::lexical_cast<std::string>(rp.crashed());
00460 run["time REAL"] = boost::lexical_cast<std::string>(rp.getTimeUsed());
00461 run["memory REAL"] = boost::lexical_cast<std::string>((double)rp.getMemUsed() / (1024.0 * 1024.0));
00462 if (gsetup_)
00463 {
00464 run["solved BOOLEAN"] = boost::lexical_cast<std::string>(gsetup_->haveExactSolutionPath());
00465 run["valid segment fraction REAL"] = boost::lexical_cast<std::string>(gsetup_->getSpaceInformation()->getMotionValidator()->getValidMotionFraction());
00466 }
00467 else
00468 {
00469 run["solved BOOLEAN"] = boost::lexical_cast<std::string>(csetup_->haveExactSolutionPath());
00470 run["valid segment fraction REAL"] = boost::lexical_cast<std::string>(csetup_->getSpaceInformation()->getMotionValidator()->getValidMotionFraction());
00471 }
00472
00473 if (solved)
00474 {
00475 if (gsetup_)
00476 {
00477 run["approximate solution BOOLEAN"] = boost::lexical_cast<std::string>(gsetup_->getGoal()->isApproximate());
00478 run["solution difference REAL"] = boost::lexical_cast<std::string>(gsetup_->getGoal()->getDifference());
00479 run["solution length REAL"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().length());
00480 run["solution smoothness REAL"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().smoothness());
00481 run["solution clearance REAL"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().clearance());
00482 run["solution segments INTEGER"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().getStateCount() - 1);
00483 run["correct solution BOOLEAN"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().check());
00484
00485 unsigned int factor = gsetup_->getStateSpace()->getValidSegmentCountFactor();
00486 gsetup_->getStateSpace()->setValidSegmentCountFactor(factor * 4);
00487 run["correct solution strict BOOLEAN"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().check());
00488 gsetup_->getStateSpace()->setValidSegmentCountFactor(factor);
00489
00490
00491 time::point timeStart = time::now();
00492 gsetup_->simplifySolution();
00493 double timeUsed = time::seconds(time::now() - timeStart);
00494 run["simplification time REAL"] = boost::lexical_cast<std::string>(timeUsed);
00495 run["simplified solution length REAL"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().length());
00496 run["simplified solution smoothness REAL"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().smoothness());
00497 run["simplified solution clearance REAL"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().clearance());
00498 run["simplified solution segments INTEGER"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().getStateCount() - 1);
00499 run["simplified correct solution BOOLEAN"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().check());
00500 gsetup_->getStateSpace()->setValidSegmentCountFactor(factor * 4);
00501 run["simplified correct solution strict BOOLEAN"] = boost::lexical_cast<std::string>(gsetup_->getSolutionPath().check());
00502 gsetup_->getStateSpace()->setValidSegmentCountFactor(factor);
00503 }
00504 else
00505 {
00506 run["approximate solution BOOLEAN"] = boost::lexical_cast<std::string>(csetup_->getGoal()->isApproximate());
00507 run["solution difference REAL"] = boost::lexical_cast<std::string>(csetup_->getGoal()->getDifference());
00508 run["solution length REAL"] = boost::lexical_cast<std::string>(csetup_->getSolutionPath().length());
00509 run["solution clearance REAL"] = boost::lexical_cast<std::string>(csetup_->getSolutionPath().asGeometric().clearance());
00510 run["solution segments INTEGER"] = boost::lexical_cast<std::string>(csetup_->getSolutionPath().getControlCount());
00511 run["correct solution BOOLEAN"] = boost::lexical_cast<std::string>(csetup_->getSolutionPath().check());
00512 }
00513 }
00514
00515 base::PlannerData pd;
00516 planners_[i]->getPlannerData(pd);
00517 run["graph states INTEGER"] = boost::lexical_cast<std::string>(pd.states.size());
00518 unsigned long edges = 0;
00519 for (unsigned int k = 0 ; k < pd.edges.size() ; ++k)
00520 edges += pd.edges[k].size();
00521 run["graph motions INTEGER"] = boost::lexical_cast<std::string>(edges);
00522
00523 for (std::map<std::string, std::string>::const_iterator it = pd.properties.begin() ; it != pd.properties.end() ; ++it)
00524 run[it->first] = it->second;
00525
00526
00527 try
00528 {
00529 if (postRun_)
00530 {
00531 msg_.inform("Executing post-run event for run %d of planner %s ...", status_.activeRun, status_.activePlanner.c_str());
00532 postRun_(planners_[i], run);
00533 msg_.inform("Completed execution of post-run event");
00534 }
00535 }
00536 catch(std::runtime_error &e)
00537 {
00538 std::stringstream es;
00539 es << "There was an error in the execution of the post-run event for run " << status_.activeRun << " of planner " << status_.activePlanner << std::endl;
00540 es << "*** " << e.what() << std::endl;
00541 std::cerr << es.str();
00542 msg_.error(es.str());
00543 }
00544
00545 exp_.planners[i].runs.push_back(run);
00546 }
00547 catch(std::runtime_error &e)
00548 {
00549 std::stringstream es;
00550 es << "There was an error in the extraction of planner results: planner = " << status_.activePlanner << ", run = " << status_.activePlanner << std::endl;
00551 es << "*** " << e.what() << std::endl;
00552 std::cerr << es.str();
00553 msg_.error(es.str());
00554 }
00555 }
00556 }
00557
00558 status_.running = false;
00559 status_.progressPercentage = 100.0;
00560 if (req.displayProgress)
00561 {
00562 while (status_.progressPercentage > progress->count())
00563 ++(*progress);
00564 std::cout << std::endl;
00565 }
00566
00567 exp_.totalDuration = time::seconds(time::now() - exp_.startTime);
00568
00569 msg_.inform("Benchmark complete");
00570 msg::useOutputHandler(oh);
00571 msg_.inform("Benchmark complete");
00572 }