Ignore:
Timestamp:
Feb 20, 2013, 12:20:49 AM (12 years ago)
Author:
ldelgass
Message:

First pass at stats logging for vtkvis

Location:
branches/Rappture 1.2/packages/vizservers/vtkvis
Files:
4 edited

Legend:

Unmodified
Added
Removed

  • branches/Rappture 1.2/packages/vizservers/vtkvis/RpVtkRenderServer.cpp

    r3262 r3312  
    1212#include <unistd.h>
    1313#include <signal.h>
    14 
    15 #ifdef WANT_TRACE
     14#include <sys/types.h>
     15#include <sys/stat.h>
     16#include <fcntl.h>
    1617#include <sys/time.h>
    17 #endif
     18#include <sys/times.h>
    1819
    1920#include <string>
    2021#include <sstream>
     22
     23#include <tcl.h>
    2124
    2225#include "Trace.h"
    … …  
    3437using namespace Rappture::VtkVis;
    3538
     39Stats Rappture::VtkVis::g_stats;
     40
    3641int Rappture::VtkVis::g_fdIn = STDIN_FILENO; ///< Input file descriptor
    3742int Rappture::VtkVis::g_fdOut = STDOUT_FILENO; ///< Output file descriptor
    … …  
    4045Renderer *Rappture::VtkVis::g_renderer = NULL; ///< Main render worker
    4146ReadBuffer *Rappture::VtkVis::g_inBufPtr = NULL; ///< Socket read buffer
    42 
    43 #define ELAPSED_TIME(t1, t2) \
    44     ((t1).tv_sec == (t2).tv_sec ? (((t2).tv_usec - (t1).tv_usec)/1.0e+3f) : \
    45      (((t2).tv_sec - (t1).tv_sec))*1.0e+3f + (float)((t2).tv_usec - (t1).tv_usec)/1.0e+3f)
    4647
    4748#ifdef USE_THREADS
    … …  
    193194#endif /*USE_THREADS*/
    194195
     196static int
     197getFileLock()
     198{
     199    int numTries;
     200
     201    for (numTries = 0; numTries < 10; numTries++) {
     202        int f;
     203
     204        f = open(LOCKFILE, O_TRUNC | O_CREAT | O_EXCL | O_WRONLY, 0600);
     205        if (f >= 0) {
     206            char buf[200];
     207            ssize_t numWritten;
     208            size_t numBytes;
     209
     210            sprintf(buf, "%d\n", getpid());
     211            numBytes = strlen(buf);
     212            numWritten = write(f, buf, numBytes);
     213            if (numWritten != (ssize_t)numBytes) {
     214                ERROR("Wrote short lock file");
     215            }
     216            close(f);
     217            return 0;
     218        }
     219        sleep(1);                       /* Wait for lock to release. */
     220    }
     221    ERROR("Failed to open lock file");
     222    return -1;
     223}
     224
     225static void
     226releaseFileLock()
     227{
     228    unlink(LOCKFILE);
     229}
     230
     231int
     232Rappture::VtkVis::writeToStatsFile(const char *s, size_t length)
     233{
     234    int f;
     235    ssize_t numWritten;
     236    if (access(STATSDIR, X_OK) != 0) {
     237        mkdir(STATSDIR, 0770);
     238    }
     239    if (getFileLock() < 0) {
     240        return -1;
     241    }
     242    f = open(STATSFILE, O_APPEND | O_CREAT | O_WRONLY, 0600);
     243    releaseFileLock();
     244    if (f < 0) {
     245        return -1;
     246    }
     247    numWritten = write(f, s, length);
     248    if (numWritten != (ssize_t)length) {
     249        close(f);
     250        return -1;
     251    }
     252    close(f);
     253    return 0;
     254}
     255
     256static int
     257serverStats(int code)
     258{
     259    double start, finish;
     260    char buf[BUFSIZ];
     261    Tcl_DString ds;
     262    int result;
     263
     264    {
     265        struct timeval tv;
     266
     267        /* Get ending time.  */
     268        gettimeofday(&tv, NULL);
     269        finish = CVT2SECS(tv);
     270        tv = g_stats.start;
     271        start = CVT2SECS(tv);
     272    }
     273    /*
     274     * Session information:
     275     *   1. Start date of session in seconds.
     276     *   2. Process ID
     277     *   3. Number of frames returned.
     278     *   4. Number of bytes total returned (in frames).
     279     *   5. Total elapsed time of all commands.
     280     *   6. Total elapsed time of session.
     281     *   7. Exit code of vizserver.
     282     *   8. User time. 
     283     *   9. System time.
     284     *  10. Maximum resident size.
     285     */
     286
     287    Tcl_DStringInit(&ds);
     288   
     289    Tcl_DStringAppendElement(&ds, "render_stop");
     290    /* renderer */
     291    Tcl_DStringAppendElement(&ds, "renderer");
     292    Tcl_DStringAppendElement(&ds, "vtkvis");
     293    /* pid */
     294    Tcl_DStringAppendElement(&ds, "pid");
     295    sprintf(buf, "%d", getpid());
     296    Tcl_DStringAppendElement(&ds, buf);
     297    /* host */
     298    Tcl_DStringAppendElement(&ds, "host");
     299    gethostname(buf, BUFSIZ-1);
     300    buf[BUFSIZ-1] = '\0';
     301    Tcl_DStringAppendElement(&ds, buf);
     302    /* date */
     303    Tcl_DStringAppendElement(&ds, "date");
     304    strcpy(buf, ctime(&g_stats.start.tv_sec));
     305    buf[strlen(buf) - 1] = '\0';
     306    Tcl_DStringAppendElement(&ds, buf);
     307    /* date_secs */
     308    Tcl_DStringAppendElement(&ds, "date_secs");
     309    sprintf(buf, "%ld", g_stats.start.tv_sec);
     310    Tcl_DStringAppendElement(&ds, buf);
     311    /* num_frames */
     312    Tcl_DStringAppendElement(&ds, "num_frames");
     313    sprintf(buf, "%lu", (unsigned long int)g_stats.nFrames);
     314    Tcl_DStringAppendElement(&ds, buf);
     315    /* frame_bytes */
     316    Tcl_DStringAppendElement(&ds, "frame_bytes");
     317    sprintf(buf, "%lu", (unsigned long int)g_stats.nBytes);
     318    Tcl_DStringAppendElement(&ds, buf);
     319    /* num_commands */
     320    Tcl_DStringAppendElement(&ds, "num_commands");
     321    sprintf(buf, "%lu", (unsigned long int)g_stats.nCommands);
     322    Tcl_DStringAppendElement(&ds, buf);
     323    /* cmd_time */
     324    Tcl_DStringAppendElement(&ds, "cmd_time");
     325    sprintf(buf, "%g", g_stats.cmdTime);
     326    Tcl_DStringAppendElement(&ds, buf);
     327    /* session_time */
     328    Tcl_DStringAppendElement(&ds, "session_time");
     329    sprintf(buf, "%g", finish - start);
     330    Tcl_DStringAppendElement(&ds, buf);
     331    /* status */
     332    Tcl_DStringAppendElement(&ds, "status");
     333    sprintf(buf, "%d", code);
     334    Tcl_DStringAppendElement(&ds, buf);
     335    {
     336        long clocksPerSec = sysconf(_SC_CLK_TCK);
     337        double clockRes = 1.0 / clocksPerSec;
     338        struct tms tms;
     339
     340        memset(&tms, 0, sizeof(tms));
     341        times(&tms);
     342        /* utime */
     343        Tcl_DStringAppendElement(&ds, "utime");
     344        sprintf(buf, "%g", tms.tms_utime * clockRes);
     345        Tcl_DStringAppendElement(&ds, buf);
     346        /* stime */
     347        Tcl_DStringAppendElement(&ds, "stime");
     348        sprintf(buf, "%g", tms.tms_stime * clockRes);
     349        Tcl_DStringAppendElement(&ds, buf);
     350        /* cutime */
     351        Tcl_DStringAppendElement(&ds, "cutime");
     352        sprintf(buf, "%g", tms.tms_cutime * clockRes);
     353        Tcl_DStringAppendElement(&ds, buf);
     354        /* cstime */
     355        Tcl_DStringAppendElement(&ds, "cstime");
     356        sprintf(buf, "%g", tms.tms_cstime * clockRes);
     357        Tcl_DStringAppendElement(&ds, buf);
     358    }
     359    Tcl_DStringAppend(&ds, "\n", -1);
     360    result = writeToStatsFile(Tcl_DStringValue(&ds),
     361                              Tcl_DStringLength(&ds));
     362    Tcl_DStringFree(&ds);
     363    return result;
     364}
     365
    195366static void
    196367initService()
    … …  
    229400exitService()
    230401{
     402    serverStats(0);
     403
    231404    // close log file
    232405    if (g_fLog != NULL) {
    … …  
    255428            g_renderer->getRenderedFrame(imgData);
    256429            queueFrame(queue, imgData);
     430            g_stats.nFrames++;
     431            g_stats.nBytes += imgData->GetDataSize() * imgData->GetDataTypeSize();
    257432        } else {
    258433            TRACE("No render required");
    … …  
    299474    initLog();
    300475
     476    memset(&g_stats, 0, sizeof(g_stats));
     477    gettimeofday(&g_stats.start, NULL);
     478
    301479    TRACE("Starting VTKVis Server");
    302480
    … …  
    353531            g_renderer->getRenderedFrame(imgData);
    354532            writeFrame(g_fdOut, imgData);
     533            g_stats.nFrames++;
     534            g_stats.nBytes += imgData->GetDataSize() * imgData->GetDataTypeSize();
    355535        } else {
    356536            TRACE("No render required");

  • branches/Rappture 1.2/packages/vizservers/vtkvis/RpVtkRenderServer.h

    r3177 r3312  
    99#define __RAPPTURE_VTKVIS_RENDERSERVER_H__
    1010
     11#include <sys/types.h>
     12#include <sys/time.h>
     13
    1114namespace Rappture {
    1215namespace VtkVis {
    1316
    1417class Renderer;
     18
     19#define MSECS_ELAPSED(t1, t2) \
     20    ((t1).tv_sec == (t2).tv_sec ? (((t2).tv_usec - (t1).tv_usec)/1.0e+3) : \
     21     (((t2).tv_sec - (t1).tv_sec))*1.0e+3 + (double)((t2).tv_usec - (t1).tv_usec)/1.0e+3)
     22
     23#define CVT2SECS(x)  ((double)(x).tv_sec) + ((double)(x).tv_usec * 1.0e-6)
     24
     25#define STATSDIR        "/var/tmp/visservers"
     26#define STATSFILE       STATSDIR "/" "vtkvis_log.tcl"
     27#define LOCKFILE        STATSDIR "/" "LCK..vtkvis"
     28
     29typedef struct {
     30    pid_t pid;
     31    size_t nFrames;         /**< # of frames sent to client. */
     32    size_t nBytes;          /**< # of bytes for all frames. */
     33    size_t nCommands;       /**< # of commands executed */
     34    double cmdTime;         /**< Elasped time spend executing commands. */
     35    struct timeval start;   /**< Start of elapsed time. */
     36} Stats;
     37
     38extern Stats g_stats;
    1539
    1640extern int g_fdIn;
    … …  
    2145extern ReadBuffer *g_inBufPtr;
    2246
     47extern int writeToStatsFile(const char *s, size_t length);
     48
    2349}
    2450}

  • branches/Rappture 1.2/packages/vizservers/vtkvis/RpVtkRenderer.cpp

    r3270 r3312  
    4747#include "Trace.h"
    4848
    49 #define ELAPSED_TIME(t1, t2) \
    50     ((t1).tv_sec == (t2).tv_sec ? (((t2).tv_usec - (t1).tv_usec)/1.0e+3f) : \
    51      (((t2).tv_sec - (t1).tv_sec))*1.0e+3f + (float)((t2).tv_usec - (t1).tv_usec)/1.0e+3f)
     49#define MSECS_ELAPSED(t1, t2) \
     50    ((t1).tv_sec == (t2).tv_sec ? (((t2).tv_usec - (t1).tv_usec)/1.0e+3) : \
     51     (((t2).tv_sec - (t1).tv_sec))*1.0e+3 + (double)((t2).tv_usec - (t1).tv_usec)/1.0e+3)
    5252
    5353using namespace Rappture::VtkVis;
    … …  
    41954195    static double accum = 0;
    41964196    numFrames++;
    4197     accum += ELAPSED_TIME(t1, t2);
     4197    accum += MSECS_ELAPSED(t1, t2);
    41984198#endif
    4199     TRACE("Readback time: %g ms", ELAPSED_TIME(t1, t2));
     4199    TRACE("Readback time: %g ms", MSECS_ELAPSED(t1, t2));
    42004200    TRACE("Readback avg: %g ms", accum/numFrames);
    42014201    if (glGetError() != GL_NO_ERROR) {

  • branches/Rappture 1.2/packages/vizservers/vtkvis/RpVtkRendererCmd.cpp

    r3266 r3312  
    21112111              Tcl_Obj *const *objv)
    21122112{
    2113     int cinfoc;
    2114     Tcl_Obj **cinfov = NULL;
    2115     if (Tcl_ListObjGetElements(interp, objv[1], &cinfoc, &cinfov) != TCL_OK) {
    2116         return TCL_ERROR;
    2117     }
    2118     if ((cinfoc % 2) != 0) {
    2119         TRACE("cinfoc: %d", cinfoc);
    2120         Tcl_AppendResult(interp, "wrong # elements in clientinfo: should be ",
    2121                          "{name value name value...}", (char*)NULL);
    2122         return TCL_ERROR;
    2123     }
    2124     TRACE("Client Info: %d items", cinfoc/2);
    2125     for (int i = 0; i < cinfoc; i += 2) {
    2126         TRACE("%s = %s", Tcl_GetString(cinfov[i]), Tcl_GetString(cinfov[i+1]));
    2127     }
    2128     return TCL_OK;
     2113    Tcl_DString ds;
     2114    int result;
     2115    int i;
     2116    char buf[BUFSIZ];
     2117
     2118    Tcl_DStringInit(&ds);
     2119    Tcl_DStringAppendElement(&ds, "render_start");
     2120    /* renderer */
     2121    Tcl_DStringAppendElement(&ds, "renderer");
     2122    Tcl_DStringAppendElement(&ds, "vtkvis");
     2123    /* pid */
     2124    Tcl_DStringAppendElement(&ds, "pid");
     2125    sprintf(buf, "%d", getpid());
     2126    Tcl_DStringAppendElement(&ds, buf);
     2127    /* host */
     2128    Tcl_DStringAppendElement(&ds, "host");
     2129    gethostname(buf, BUFSIZ-1);
     2130    buf[BUFSIZ-1] = '\0';
     2131    Tcl_DStringAppendElement(&ds, buf);
     2132    /* date */
     2133    Tcl_DStringAppendElement(&ds, "date");
     2134    strcpy(buf, ctime(&Rappture::VtkVis::g_stats.start.tv_sec));
     2135    buf[strlen(buf) - 1] = '\0';
     2136    Tcl_DStringAppendElement(&ds, buf);
     2137    /* date_secs */
     2138    Tcl_DStringAppendElement(&ds, "date_secs");
     2139    sprintf(buf, "%ld", Rappture::VtkVis::g_stats.start.tv_sec);
     2140    Tcl_DStringAppendElement(&ds, buf);
     2141    /* Client arguments. */
     2142    for (i = 1; i < objc; i++) {
     2143        Tcl_DStringAppendElement(&ds, Tcl_GetString(objv[i]));
     2144    }
     2145    Tcl_DStringAppend(&ds, "\n", 1);
     2146    result = Rappture::VtkVis::writeToStatsFile(Tcl_DStringValue(&ds),
     2147                                                Tcl_DStringLength(&ds));
     2148    Tcl_DStringFree(&ds);
     2149    return result;
    21292150}
    21302151
    … …  
    96639684        Tcl_DStringAppend(&command, (char *)buffer, numBytes);
    96649685        if (Tcl_CommandComplete(Tcl_DStringValue(&command))) {
     9686            struct timeval start, finish;
     9687            gettimeofday(&start, NULL);
    96659688            status = ExecuteCommand(interp, &command);
     9689            gettimeofday(&finish, NULL);
     9690            g_stats.cmdTime += (MSECS_ELAPSED(start, finish) / 1.0e+3);
     9691            g_stats.nCommands++;
    96669692            if (status == TCL_BREAK) {
    96679693                return 1;               /* This was caused by a "imgflush"
Note: See TracChangeset for help on using the changeset viewer.