Skip to content

Commit

Permalink
- Time measurements now use a binary format instead of csv (a format …
Browse files Browse the repository at this point in the history 
…description is part of the generated xml)

git-svn-id: https://openmodelica.org/svn/OpenModelica/trunk@8058 f25d12d1-65f4-0310-ae8a-bbce733d8d8e
  • Loading branch information
@sjoelund
sjoelund committed Mar 2, 2011
1 parent 9f2dcd2 commit 9c202be
Show file tree
Hide file tree
Showing 3 changed files with 90 additions and 47 deletions.
10 changes: 5 additions & 5 deletions Compiler/scripts/default_profiling.xsl
View file
Expand Up @@ -33,15 +33,15 @@
</head>

<body>
<h1>Model information for <xsl:value-of select="modelinfo/name"/></h1>
<h1>Profiling information for <xsl:value-of select="modelinfo/name"/></h1>

<h2>Information</h2>
<p>All times are measured using a real-time wall clock. This means context switching produces bad worst-case execution times (max times) for blocks. If you want better results, use a CPU-time clock or run the command using real-time priviliges (avoiding context switches).</p>
<p>Note that for blocks where the individual execution time is close to the accuracy of the real-time clock, the maximum measured time may deviate a lot from the average.</p>
<p>For more details, see <a href="{modelinfo/prefix}_prof.csv"><xsl:value-of select="modelinfo/name"/>_prof.csv</a>.</p>
<p>For more details, see <a href="{modelinfo/prefix}_prof.xml"><xsl:value-of select="modelinfo/name"/>_prof.xml</a>.</p>

<h2>Summary</h2>
<p>What solver/settings were used?</p>
<p>What solver/settings were used? This is missing :(</p>
<table>
<tr><th class="name">Task</th><th>Time</th><th><abbr title="Fraction of total simulation time">Fraction</abbr></th></tr>
<tr><td class="name"><abbr title="Choosing solver, allocating data structures, etc (does not include reading the parameter start-values from file)">Pre-Initialization</abbr></td><td><xsl:value-of select="modelinfo/preinitTime"/></td><td><xsl:value-of select="format-number(100 * modelinfo/preinitTime div modelinfo/totalTime,'##0.00')"/>%</td></tr>
Expand All @@ -50,8 +50,8 @@
<tr><td class="name">Creating output file</td><td><xsl:value-of select="modelinfo/outputTime"/></td><td><xsl:value-of select="format-number(100 * modelinfo/outputTime div modelinfo/totalTime,'##0.00')"/>%</td></tr>
<tr><td class="name">Linearization</td><td><xsl:value-of select="modelinfo/linearizeTime"/></td><td><xsl:value-of select="format-number(100 * modelinfo/linearizeTime div modelinfo/totalTime,'##0.00')"/>%</td></tr>
<tr><td class="name">Time steps (incl.integration?)</td><td><xsl:value-of select="modelinfo/totalStepsTime"/></td><td><xsl:value-of select="format-number(100 * modelinfo/totalStepsTime div modelinfo/totalTime,'##0.00')"/>%</td></tr>
<tr><td class="name">Overhead</td><td><xsl:value-of select="modelinfo/overheadTime"/></td><td><xsl:value-of select="format-number(100 * modelinfo/overheadTime div modelinfo/totalTime,'##0.00')"/>%</td></tr>
<tr><td class="name">Unknown</td><td><xsl:value-of select="modelinfo/totalTime - modelinfo/overheadTime - modelinfo/totalStepsTime - modelinfo/linearizeTime - modelinfo/outputTime - modelinfo/eventTime - modelinfo/initTime"/></td>
<tr><td class="name"><abbr title="Overhead from creating {profilingdataheader/filename}. The overhead from sampling the real-time clock is embedded in the other times.">Overhead</abbr></td><td><xsl:value-of select="modelinfo/overheadTime"/></td><td><xsl:value-of select="format-number(100 * modelinfo/overheadTime div modelinfo/totalTime,'##0.00')"/>%</td></tr>
<tr><td class="name"><abbr title="Some subparts are not measured (between steps, etc), and some overlap (function calls during initialization)">Unknown</abbr></td><td><xsl:value-of select="modelinfo/totalTime - modelinfo/overheadTime - modelinfo/totalStepsTime - modelinfo/linearizeTime - modelinfo/outputTime - modelinfo/eventTime - modelinfo/initTime"/></td>
<td><xsl:value-of select="format-number(100 * (modelinfo/totalTime - modelinfo/overheadTime - modelinfo/totalStepsTime - modelinfo/linearizeTime - modelinfo/outputTime - modelinfo/eventTime - modelinfo/initTime - modelinfo/preinitTime) div modelinfo/totalTime,'##0.00')"/>%</td></tr>
<tr><td class="name">Total simulation time</td><td><xsl:value-of select="modelinfo/totalTime"/></td><td>100.00%</td></tr>
</table>
Expand Down
65 changes: 48 additions & 17 deletions c_runtime/simulation_modelinfo.c
View file
Expand Up @@ -39,14 +39,15 @@ static void indent(FILE *fout, int n) {
while (n--) fputc(' ', fout);
}

static void printPlotCommand(FILE *plt, const char *prefix, int i, int id) {
static void printPlotCommand(FILE *plt, const char *prefix, int numFnsAndBlocks, int i, int id) {
const char *format = "plot \"%s_prof.data\" binary format=\"%%*uint32%%2double%%*%duint32%%%ddouble\" using 1:%d w l lw 1\n";
if (!plt) return;
fputs("set terminal png size 32,32\n", plt);
fprintf(plt, "set output \"%s_prof.%d.thumb.png\"\n", prefix, id);
fprintf(plt, "plot \"%s_prof.csv\" using 2:%d w l lw 1\n", prefix, 2*i+5);
fprintf(plt, format, prefix, numFnsAndBlocks, numFnsAndBlocks, 2+i);
fputs("set terminal svg\n", plt);
fprintf(plt, "set output \"%s_prof.%d.svg\"\n", prefix, id);
fprintf(plt, "plot \"%s_prof.csv\" using 2:%d\n", prefix, 2*i+5);
fprintf(plt, format, prefix, numFnsAndBlocks, numFnsAndBlocks, 2+i);
}

static void printInfoTag(FILE *fout, int level, const omc_fileInfo info) {
Expand All @@ -65,10 +66,10 @@ static void printVars(FILE *fout, int level, int n, const struct omc_varInfo *va
}
}

static void printFunctions(FILE *fout, FILE *plt, const char *modelFilePrefix, int n, const struct omc_functionInfo *funcs) {
static void printFunctions(FILE *fout, FILE *plt, const char *modelFilePrefix, DATA *data, const struct omc_functionInfo *funcs) {
int i;
for (i=0; i<n; i++) {
printPlotCommand(plt, modelFilePrefix, i, funcs[i].id);
for (i=0; i<data->nFunctions; i++) {
printPlotCommand(plt, modelFilePrefix, data->nFunctions+data->nProfileBlocks, i, funcs[i].id);
rt_clear(i + SIM_TIMER_FIRST_FUNCTION);
indent(fout,2);
fprintf(fout, "<function id=\"%d\">\n", funcs[i].id);
Expand All @@ -86,7 +87,7 @@ static void printProfileBlocks(FILE *fout, FILE *plt, DATA *data) {
int i;
for (i = data->nFunctions; i < data->nFunctions + data->nProfileBlocks; i++) {
const struct omc_equationInfo *eq = &data->equationInfo[data->equationInfo_reverse_prof_index[i-data->nFunctions]];
printPlotCommand(plt, data->modelFilePrefix, i, eq->id);
printPlotCommand(plt, data->modelFilePrefix, data->nFunctions+data->nProfileBlocks, i, eq->id);
rt_clear(i + SIM_TIMER_FIRST_FUNCTION);
indent(fout,2);fprintf(fout, "<profileblock>\n");
indent(fout,4);fprintf(fout, "<ref refid=\"%d\"/>\n", (int) eq->id);
Expand All @@ -110,6 +111,32 @@ static void printEquations(FILE *fout, int n, const struct omc_equationInfo *eqn
}
}

static void printProfilingDataHeader(FILE *fout, DATA *data) {
int i;
indent(fout, 2); fprintf(fout, "<filename>%s_prof.data</filename>\n", data->modelFilePrefix);
indent(fout, 2); fprintf(fout, "<format>\n");
indent(fout, 4); fprintf(fout, "<double>step</double>\n");
indent(fout, 4); fprintf(fout, "<double>time</double>\n");
indent(fout, 4); fprintf(fout, "<double>cpu time</double>\n");
for (i = 0; i < globalData->nFunctions; i++) {
const char *name = globalData->functionNames[i].name;
indent(fout, 4); fprintf(fout, "<uint32>%s (calls)</uint32>\n", name);
}
for (i = 0; i < globalData->nProfileBlocks; i++) {
const char *name = globalData->equationInfo[globalData->equationInfo_reverse_prof_index[i]].name;
indent(fout, 4); fprintf(fout, "<uint32>%s (calls)</uint32>\n", name);
}
for (i = 0; i < globalData->nFunctions; i++) {
const char *name = globalData->functionNames[i].name;
indent(fout, 4); fprintf(fout, "<double>%s (cpu time)</double>\n", name);
}
for (i = 0; i < globalData->nProfileBlocks; i++) {
const char *name = globalData->equationInfo[globalData->equationInfo_reverse_prof_index[i]].name;
indent(fout, 4); fprintf(fout, "<double>%s (cpu time)</double>\n", name);
}
indent(fout, 2); fprintf(fout, "</format>\n");
}

int printModelInfo(DATA *data, const char *filename, const char *plotfile) {
static char buf[256];
FILE *fout = fopen(filename, "w");
Expand All @@ -129,10 +156,9 @@ int printModelInfo(DATA *data, const char *filename, const char *plotfile) {
}
if (plotCommands) {
fputs("set terminal svg\n", plotCommands);
fputs("set datafile separator \",\"\n", plotCommands);
fputs("set nokey\n", plotCommands);
/* The column containing the time spent to calculate each step */
printPlotCommand(plotCommands, data->modelFilePrefix, -1, 999);
printPlotCommand(plotCommands, data->modelFilePrefix, data->nFunctions+data->nProfileBlocks, 0, 999);
}
/* The doctype is needed for id() lookup to work properly */
fprintf(fout, "<!DOCTYPE doc [\
Expand Down Expand Up @@ -169,10 +195,14 @@ int printModelInfo(DATA *data, const char *filename, const char *plotfile) {
indent(fout, 2); fprintf(fout, "<linearizeTime>%f</linearizeTime>\n", rt_accumulated(SIM_TIMER_LINEARIZE));
indent(fout, 2); fprintf(fout, "<totalTime>%f</totalTime>\n", rt_accumulated(SIM_TIMER_TOTAL));
indent(fout, 2); fprintf(fout, "<totalStepsTime>%f</totalStepsTime>\n", rt_total(SIM_TIMER_STEP));
indent(fout, 2); fprintf(fout, "<numStep>%d</numStep>\n", rt_ncall_total(SIM_TIMER_STEP));
indent(fout, 2); fprintf(fout, "<numStep>%d</numStep>\n", (int) rt_ncall_total(SIM_TIMER_STEP));
indent(fout, 2); fprintf(fout, "<maxTime>%.9f</maxTime>\n", rt_max_accumulated(SIM_TIMER_STEP));
fprintf(fout, "</modelinfo>\n");

fprintf(fout, "<profilingdataheader>\n");
printProfilingDataHeader(fout, data);
fprintf(fout, "</profilingdataheader>\n");

fprintf(fout, "<variables>\n");
printVars(fout, 2, data->nStates, data->statesNames);
printVars(fout, 2, data->nStates, data->stateDerivativesNames);
Expand All @@ -187,7 +217,7 @@ int printModelInfo(DATA *data, const char *filename, const char *plotfile) {
fprintf(fout, "</variables>\n");

fprintf(fout, "<functions>\n");
printFunctions(fout, plotCommands, data->modelFilePrefix, data->nFunctions, data->functionNames);
printFunctions(fout, plotCommands, data->modelFilePrefix, data, data->functionNames);
fprintf(fout, "</functions>\n");

fprintf(fout, "<equations>\n");
Expand All @@ -204,6 +234,7 @@ int printModelInfo(DATA *data, const char *filename, const char *plotfile) {
if (plotCommands) {
char *omhome;
char *buf;
int genHtmlRes;
omhome = getenv("OPENMODELICAHOME");
buf = malloc(200 + 2*strlen(plotfile) + (omhome ? strlen(omhome) : 0));
#if defined(__MINGW32__) || defined(_MSC_VER)
Expand All @@ -220,14 +251,14 @@ int printModelInfo(DATA *data, const char *filename, const char *plotfile) {
#endif
if (omhome) {
sprintf(buf, "xsltproc -o %s_prof.html %s/share/omc/scripts/default_profiling.xsl %s_prof.xml", data->modelFilePrefix, omhome, data->modelFilePrefix);
if (0 != system(buf)) {
fprintf(stdout, "Time measurements stored in %s_prof.xml (for XSL transforms) and %s_prof.csv (the raw data)\n", data->modelFilePrefix, data->modelFilePrefix);
} else {
fprintf(stdout, "Time measurements stored in %s_prof.html (human-readable), %s_prof.xml (for XSL transforms) and %s_prof.csv (the raw data)\n", data->modelFilePrefix, data->modelFilePrefix, data->modelFilePrefix);
}
genHtmlRes = system(buf);
} else {
fprintf(stdout, "Time measurements stored in %s_prof.xml (for XSL transforms) and %s_prof.csv (the raw data)\n", data->modelFilePrefix, data->modelFilePrefix);
strcpy(buf, "OPENMODELICAHOME missing");
genHtmlRes = 1;
}
if (genHtmlRes)
fprintf(stderr, "Warning: Failed to generate html version of profiling results: %s\n", buf);
fprintf(stdout, "Time measurements stored in %s_prof.html (human-readable), %s_prof.xml (for XSL transforms)\n", data->modelFilePrefix, data->modelFilePrefix);
free(buf);
}
return 0;
Expand Down
62 changes: 37 additions & 25 deletions c_runtime/solver_main.cpp
View file
Expand Up @@ -36,11 +36,13 @@
#include "simulation_runtime.h"
#include "options.h"
#include <cmath>
#include <cstring>
#include <string.h>
#include <iostream>
#include <iomanip>
#include <algorithm>
#include <cstdarg>
#include <stdint.h>
#include <errno.h>
#include "rtclock.h"

using namespace std;
Expand Down Expand Up @@ -450,21 +452,18 @@ solver_main(int argc, char** argv, double &start, double &stop, double &step,
cout << "Start numerical solver from " << globalData->timeValue << " to "
<< stop << endl;
}
std::ofstream fmt;
long stepNo = 0;
if (measure_time_flag)
{
const string filename = string(globalData->modelFilePrefix) + "_prof.csv";
fmt.open(filename.c_str());
fmt << "step,time,solver time";
for (int i = 0; i < globalData->nFunctions; i++)
fmt << "," << globalData->functionNames[i].name << ",";
for (int i = 0; i < globalData->nProfileBlocks; i++)
fmt << ","
<< globalData->equationInfo[globalData->equationInfo_reverse_prof_index[i]].name
<< ",";
fmt << endl;
FILE *fmt = NULL;
uint32_t stepNo = 0;
if (measure_time_flag) {
const string filename = string(globalData->modelFilePrefix) + "_prof.data";
fmt = fopen(filename.c_str(), "wb");
if (!fmt) {
measure_time_flag = 0;
fprintf(stderr, "Warning: Disabled time measurements because the output file could not be opened: %s\n", strerror(errno));
fclose(fmt);
fmt = NULL;
}
}

try
{
Expand Down Expand Up @@ -555,19 +554,30 @@ solver_main(int argc, char** argv, double &start, double &stop, double &step,
saveall();
if (measure_time_flag)
{
double tmpdbl;
uint32_t tmpint;
rt_tick(SIM_TIMER_OVERHEAD);
rt_accumulate(SIM_TIMER_STEP);
fmt << stepNo++ << "," << globalData->timeValue << ","
<< rt_accumulated(SIM_TIMER_STEP);
for (int i = 0; i < globalData->nFunctions; i++)
fmt << "," << rt_ncall(i + SIM_TIMER_FIRST_FUNCTION) << ","
<< rt_accumulated(i + SIM_TIMER_FIRST_FUNCTION);
for (int i = globalData->nFunctions; i < globalData->nFunctions
+ globalData->nProfileBlocks; i++)
fmt << "," << rt_ncall(i + SIM_TIMER_FIRST_FUNCTION) << ","
<< rt_accumulated(i + SIM_TIMER_FIRST_FUNCTION);
fmt << endl;
/* Disable time measurements if we have trouble writing to the file... */
measure_time_flag = measure_time_flag && 1 == fwrite(&stepNo, sizeof(uint32_t), 1, fmt);
stepNo++;
measure_time_flag = measure_time_flag && 1 == fwrite(&globalData->timeValue, sizeof(double), 1, fmt);
tmpdbl = rt_accumulated(SIM_TIMER_STEP);
measure_time_flag = measure_time_flag && 1 == fwrite(&tmpdbl, sizeof(double), 1, fmt);
for (int i = 0; i < globalData->nFunctions + globalData->nProfileBlocks; i++) {
tmpint = rt_ncall(i + SIM_TIMER_FIRST_FUNCTION);
measure_time_flag = measure_time_flag && 1 == fwrite(&tmpint, sizeof(uint32_t), 1, fmt);
}
for (int i = 0; i < globalData->nFunctions + globalData->nProfileBlocks; i++) {
tmpdbl = rt_accumulated(i + SIM_TIMER_FIRST_FUNCTION);
measure_time_flag = measure_time_flag && 1 == fwrite(&tmpdbl, sizeof(double), 1, fmt);
}
rt_accumulate(SIM_TIMER_OVERHEAD);
if (!measure_time_flag) {
fprintf(stderr, "Warning: Disabled time measurements because the output file could not be generated: %s\n", strerror(errno));
fclose(fmt);
fmt = NULL;
}
}
SaveZeroCrossings();
sim_result->emit();
Expand Down Expand Up @@ -601,6 +611,7 @@ solver_main(int argc, char** argv, double &start, double &stop, double &step,
{ // terminated from assert, etc.
cout << "Simulation terminated at time " << globalData->timeValue
<< endl;
if (fmt) fclose(fmt);
return -1;
}
}
Expand All @@ -614,6 +625,7 @@ solver_main(int argc, char** argv, double &start, double &stop, double &step,
}

deinitializeEventData();
if (fmt) fclose(fmt);

return 0;
}
Expand Down

0 comments on commit 9c202be

Please sign in to comment.