Changeset 8228

Timestamp:

02/03/10 11:59:50 (3 years ago)

Author:

sson

Message:

added some timing measurement calls for bmi and trove.

Location:

branches/as-branch

Files:

• src/client/sysint/client-state-machine.c (modified) (1 diff)
• src/common/misc/state-machine-fns.c (modified) (1 diff)
• src/io/bmi/bmi_tcp/bmi-tcp.c (modified) (4 diffs)
• src/server/io.sm (modified) (7 diffs)
• src/server/kmeans.sm (modified) (4 diffs)
• src/server/pipeline.sm (modified) (9 diffs)
• test/active-storage/simple.c (modified) (9 diffs)
• test/active-storage/test_kmeans.c (modified) (2 diffs)

branches/as-branch/src/client/sysint/client-state-machine.c

@@ -450 +450 @@
     }
     gen_mutex_unlock(&test_mutex);
-    return js.error_code;
-}
+    return js.error_code;}
+
 
 PVFS_error PINT_client_state_machine_release(

branches/as-branch/src/common/misc/state-machine-fns.c

@@ -11 +11 @@
 #include <string.h>
 #include <assert.h>
-#include <stdlib.h> /* sson */
 
 #include "gossip.h"

branches/as-branch/src/io/bmi/bmi_tcp/bmi-tcp.c

@@ -392 +392 @@
 {
     TCP_MODE_EAGER_LIMIT = 16384,       /* 16K */
-    TCP_MODE_REND_LIMIT = 16777216*6    /* 16M */ /* sson: 96MB */
+    TCP_MODE_REND_LIMIT = 16777216*32   /* 16M */ /* sson: 96MB */
 };
 
@@ -1448 +1448 @@
                        bmi_tcp_pid, NULL, query_op->event_id,
                        query_op->actual_size);
+#if 0
+                struct timeval tv;
+                gettimeofday(&tv, NULL);
+                double t1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+                printf("end(%s): %f\n", ((query_op->send_recv==BMI_SEND)?"BMI_SEND":"BMI_RECV"), t1);
+#endif
+
 
         dealloc_tcp_method_op(query_op);
@@ -2543 +2550 @@
         PINT_HINT_GET_OP_ID(hints),
         expected_size);
-
+#if 0
+    /* sson */
+    struct timeval tv; 
+    gettimeofday(&tv, NULL);
+    double t1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+    printf("start(%s): %f\n", "BMI_RECV", t1);
+#endif
     tcp_addr_data = src->method_data;
 
@@ -3958 +3971 @@
         PINT_HINT_GET_OP_ID(hints),
         total_size);
+#if 0
+    /* sson */
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+    double t1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+    if(bmi_tracing==1) 
+        printf("start(%s): %f(event_id=%d,tcp_id=%d)\n", "BMI_SEND", t1, bmi_tcp_send_event_id, bmi_tcp_pid);
+#endif
 
     /* Three things can happen here:

branches/as-branch/src/server/io.sm

@@ -25 +25 @@
 #define NUM_OF_PARALLEL_SMS 1
 #define BUFFER_SIZE (1024*1024) /* 1MB */
+
+double bmi_time, trove_time, io_time;
+double sio, eio;
+int iotype=0; /* 1: READ, 2: WRITE */
 
 %%
@@ -180 +184 @@
     s_op->u.io.file_data.server_nr = s_op->req->u.io.server_nr;
     s_op->u.io.file_data.server_ct = s_op->req->u.io.server_ct;
+
+    if(iotype != s_op->req->u.io.io_type) {
+        iotype = s_op->req->u.io.io_type;
+        bmi_time = trove_time = 0.0;
+        io_time = 0.0;
+        printf("\n\n%s\n", (iotype==1)?"READ":"WRITE");
+    }
 
     /* on writes, we allow the bstream to be extended at EOF */
@@ -362 +373 @@
     }
 
+    struct timeval tv; 
+    gettimeofday(&tv, NULL);
+    sio = tv.tv_sec+(tv.tv_usec/1000000.0);
+
     js_p->error_code = 0;
     return SM_ACTION_COMPLETE;
@@ -377 +392 @@
     {
         pipeline_op = PINT_sm_pop_frame(smcb, &task_id, &tmp_err, 
-                                        &remaining);
+                                        &remaining);
         gossip_debug(GOSSIP_SERVER_DEBUG, 
-                     "io: nested sm returned error code: %d\n", tmp_err);
+                     "io: nested sm returned error code: %d\n", tmp_err);
         if(pipeline_op->u.pipeline.buffer) {
             if(s_op->req->u.io.io_type == PVFS_IO_READ) {
                 if(pipeline_op->u.pipeline.op != 0 && 
                    pipeline_op->u.pipeline.op != (0x5800000f))
-                    memcpy(s_op->u.io.tmp_buffer, 
-                           pipeline_op->u.pipeline.buffer, 
-                           sizeof(double)); /* FIXME */
+                    if(s_op->u.io.tmp_buffer != NULL)
+                        memcpy(s_op->u.io.tmp_buffer, 
+                               pipeline_op->u.pipeline.buffer, 
+                               sizeof(double));
                 BMI_memfree(pipeline_op->u.pipeline.address, 
                             pipeline_op->u.pipeline.buffer, 
@@ -404 +420 @@
 }
 
-                                         
 /*
  * Function: io_release()
@@ -436 +451 @@
 }
 
-/*
+
+/* 
  * Function: io_cleanup()
  *
@@ -468 +484 @@
         free(s_op->u.io.tmp_buffer); /* FIXME */
 
-    gen_mutex_destroy(&s_op->u.io.mutex); /* FIXME: */
-
+    gen_mutex_destroy(&s_op->u.io.mutex); /* FIXME */
+
+    //printf("event_id=%d\n", s_op->event_id); // always 0
+    printf("bmi_time=%f, trove_time=%f, total=%f\n", bmi_time, trove_time, bmi_time+trove_time);
+    struct timeval tv; 
+    gettimeofday(&tv, NULL);
+    eio = tv.tv_sec+(tv.tv_usec/1000000.0);
+    io_time = eio - sio;
+    printf("io_time=%f\n", io_time);
     /* let go of our encoded response buffer, if we appear to have
      * made one

branches/as-branch/src/server/kmeans.sm

@@ -16 +16 @@
 #include <assert.h>
 #include <math.h>
+#include <time.h>
 
 #include "server-config.h"
@@ -28 +29 @@
 #include "kmeans.h"
 
-#include <cuda.h>
-#include <cuda_runtime.h>
+//#include <cuda.h>
+//#include <cuda_runtime.h>
 
 extern void initGPU (float* objects, int numDataPoints,
@@ -50 +51 @@
 int device_initialized=0;
 #define MAX_ITERATIONS 500
+
+struct timeval td_start, td_end;
 
 %%
@@ -311 +314 @@
         /* initialize GPU device and allocate memory on it */
         if(device_initialized == 0) {
+            time_t start, end;
             /* initDevice(argc, argv, numObjs, numCoords, numClusters) */
+            gossip_debug(GOSSIP_IO_DEBUG, "before initGPU\n");
+            time(&start);
             initGPU(s_op->u.kmeans.objects[0], s_op->u.kmeans.numObjs,
                     s_op->u.kmeans.numCoords, s_op->u.kmeans.numClusters);
+            time(&end);
+            gossip_debug(GOSSIP_IO_DEBUG, "after initGPU: elapsed=%lf ms\n",
+                         difftime(end, start)*1000);
             /* FIXME: I don't know why this is called twice */
             device_initialized = 1;

branches/as-branch/src/server/pipeline.sm

@@ -45 +45 @@
 int NUM_CLUSTERS; /* for kmeans only */
 #define TMP_BUF_SIZ 128
+
+extern double bmi_time, trove_time; /* sson */
+double bs1, bs2, br1, br2, tr1, tr2, tw1, tw2;
 
 %%
@@ -165 +168 @@
     s_op->u.pipeline.segs = count;
 
-    if(s_op->u.pipeline.io_type == PVFS_IO_READ) {      
+    if(s_op->u.pipeline.io_type == PVFS_IO_READ) {
+        struct timeval tv; 
+        gettimeofday(&tv, NULL);
+        tr1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("start(%s): %f\n", "TROVE_READ", t1);
         ret = job_trove_bstream_read_list
             (s_op->u.pipeline.fs_id,
@@ -186 +193 @@
     }
     else if (s_op->u.pipeline.io_type == PVFS_IO_WRITE) {
+        struct timeval tv; 
+        gettimeofday(&tv, NULL);
+        br1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("start(%s): %f\n", "BMI_RECV", t1);
         ret = job_bmi_recv(s_op->u.pipeline.address,
                        (void *)s_op->u.pipeline.buffer,
@@ -191 +202 @@
                        s_op->u.pipeline.tag,
                        BMI_PRE_ALLOC, 
-                       smcb, 
+                       smcb, 
                        0, /* unsigned long status_user_tag = 0 */
                        js_p,
@@ -197 +208 @@
                        server_job_context,
                        user_opts->server_job_flow_timeout,
-                       (bmi_hint)s_op->u.pipeline.hints);
+                       (bmi_hint)s_op->u.pipeline.hints);
     }
 
@@ -235 +246 @@
     struct server_configuration_s *user_opts = get_server_config_struct();
 
+    struct timeval tv; 
+    gettimeofday(&tv, NULL);
+    if(s_op->u.pipeline.io_type==PVFS_IO_READ) {
+        tr2 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("end(%s): %f\n", "TROVE_READ", tr2);
+        trove_time += tr2-tr1;
+    }
+    else if(s_op->u.pipeline.io_type==PVFS_IO_WRITE) {
+        br2 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("end(%s): %f\n", "BMI_RECV", br2);
+        bmi_time += br2-br1;
+    }
+
     if(s_op->u.pipeline.segs == 0) {
         js_p->error_code = 0;
@@ -258 +282 @@
         assert(s_op->u.pipeline.buffer_used);
 
+        struct timeval tv; 
+        gettimeofday(&tv, NULL);
+        bs1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("start(%s): %f\n", "BMI_SEND", bs1);
+
         if(s_op->u.pipeline.op != 0) { /* AS: when op is specified */
             ret = DO_COMP; /* AS: skip sending if op is specified */ 
-            gossip_debug(GOSSIP_IO_DEBUG, "%s: parent->op != 0\n", __func__);
+            gossip_debug(GOSSIP_IO_DEBUG, "%s: s_op->u.pipeline->op != 0\n", __func__);
             js_p->error_code = ret;
             return SM_ACTION_COMPLETE;
         } 
-        else 
+        else {
             ret = job_bmi_send(s_op->u.pipeline.address,
                                s_op->u.pipeline.buffer,
@@ -278 +307 @@
                                user_opts->server_job_bmi_timeout,
                                (bmi_hint)s_op->u.pipeline.hints);
+        }
         
     }
     else if(s_op->u.pipeline.io_type == PVFS_IO_WRITE) {
+        struct timeval tv; 
+        gettimeofday(&tv, NULL);
+        tw1 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("start(%s): %f\n", "TROVE_WRITE", t1);
         ret = job_trove_bstream_write_list
             (s_op->u.pipeline.fs_id,
@@ -1179 +1213 @@
     js_p->error_code = 0;
 
+    struct timeval tv; 
+    gettimeofday(&tv, NULL);
+    if(s_op->u.pipeline.io_type == PVFS_IO_READ) {
+        bs2 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        //printf("end(%s): %f\n", "BMI_SEND", bs2);
+        //printf("bmi_time=%f\n", bmi_time);
+        bmi_time += bs2-bs1;
+    }
+    else if(s_op->u.pipeline.io_type == PVFS_IO_WRITE) {
+        tw2 = tv.tv_sec+(tv.tv_usec/1000000.0);
+        trove_time += tw2-tw1;
+    }
+
     /* FIMXE: do we really need this lock? */
     gen_mutex_lock(&parent_s_op->u.io.mutex);

branches/as-branch/test/active-storage/simple.c

@@ -14 +14 @@
     "       -g : use generated file\n"
     "       -s size : file size to generate in MB\n"
-    "       -x : test active storage module\n";
+    "       -x : test active storage module\n"
+    "       -t : test normal storage module\n";
   fprintf(stderr, help, argv0);
 }
@@ -31 +32 @@
   extern int     optind;
   int is_output_timing=0, is_print_usage = 0;
-  int _debug=0, use_gen_file = 0, use_actsto = 0;
+  int _debug=0, use_gen_file = 0, use_actsto = 0, use_normalsto=0;
 
   MPI_Offset disp, offset, file_size;
@@ -57 +58 @@
   MPI_Comm_rank( comm, &rank );
  
-  while ( (opt=getopt(argc,argv,"i:s:godhx"))!= EOF) {
+  while ( (opt=getopt(argc,argv,"i:s:godhxt"))!= EOF) {
     switch (opt) {
     case 'i': fname = optarg;
@@ -85 +86 @@
     case 'x': use_actsto = 1;
       break;
+    case 't': use_normalsto = 1;
+      break;
     default: is_print_usage = 1;
       break;
@@ -94 +97 @@
     MPI_Finalize();
     exit(1);
+  }
+  if(use_normalsto == 1 && use_actsto == 1) {
+      if(rank == 0)
+          printf("Can't test both: either normalsto or actsto\n");
+      MPI_Finalize();
+      exit(1);
   }
  
@@ -133 +142 @@
     }
 
+    stime = MPI_Wtime();
     /* Write to file */
     MPI_File_write_all( fh, buf, nitem, MPI_DOUBLE, &status );
+    etime = MPI_Wtime();
+    iotime = etime - stime;
+      
+    printf("%d: iotime (write) = %10.4f\n", rank, iotime);
 
     MPI_Get_count( &status, MPI_DOUBLE, &count );
@@ -149 +163 @@
     MPI_File_close(&fh);
   }
-  
-  MPI_File_open( comm, fname, MPI_MODE_RDWR, MPI_INFO_NULL, &fh );
-  /* Read nothing (check status) */
-  memset( &status, 0xff, sizeof(MPI_Status) );
 
   double *tmp = (double *)malloc( nitem * sizeof(double) );
-  offset = rank * nitem * type_size;
-
-  /* start I/O */
-  stime = MPI_Wtime();
-  MPI_File_read_at(fh, offset, tmp, nitem, MPI_DOUBLE, &status);
-  etime = MPI_Wtime();
-  /* end I/O */
-  iotime = etime - stime;
-
-  if(_debug==1) printf("%d: iotime = %10.4f\n", rank, iotime);
-  MPI_Reduce(&iotime, &max_iotime, 1, MPI_DOUBLE, MPI_MAX, 0, MPI_COMM_WORLD);
- 
-  sum = 0.0; /* reset sum */
-
-  /* start computation */
-  stime = MPI_Wtime();
-
-  for(i=0; i<nitem; i++) {
-      sum += tmp[i];
-  }
-
-  MPI_Reduce(&sum, &global_sum, 1, MPI_DOUBLE, MPI_MAX, 0, MPI_COMM_WORLD);
-  etime = MPI_Wtime();
-  /* end computation */
-
-  comptime = etime - stime;
-
-  if(_debug==1) printf("%d: comptime = %10.4f\n", rank, comptime);
-
-  MPI_Reduce(&comptime, &max_comptime, 1, MPI_DOUBLE, MPI_MAX, 0, MPI_COMM_WORLD);
-
-  if(rank == 0) {
-      elapsed_time = max_comptime + max_iotime;
-      printf("<<Result (SUM) with normal read>>\n"
-             "SUM              = %10.4f \n"
-             "Computation time = %10.4f sec\n"
-             "I/O time         = %10.4f sec\n"
-             "total time       = %10.4f sec\n\n", 
-             global_sum, max_comptime, max_iotime, elapsed_time);
-  }
-      
-  MPI_File_close(&fh);
+
+  if(use_normalsto == 1) {
+      MPI_File_open( comm, fname, MPI_MODE_RDWR, MPI_INFO_NULL, &fh );
+      /* Read nothing (check status) */
+      memset( &status, 0xff, sizeof(MPI_Status) );
+      
+      offset = rank * nitem * type_size;
+
+      /* start I/O */
+      stime = MPI_Wtime();
+      MPI_File_read_at(fh, offset, tmp, nitem, MPI_DOUBLE, &status);
+      etime = MPI_Wtime();
+      /* end I/O */
+      iotime = etime - stime;
+      
+      if(_debug==1) printf("%d: iotime = %10.4f\n", rank, iotime);
+      MPI_Reduce(&iotime, &max_iotime, 1, MPI_DOUBLE, MPI_MAX, 0, MPI_COMM_WORLD);
+      
+      sum = 0.0; /* reset sum */
+      
+      /* start computation */
+      stime = MPI_Wtime();
+      
+      for(i=0; i<nitem; i++) {
+          sum += tmp[i];
+      }
+      
+      MPI_Reduce(&sum, &global_sum, 1, MPI_DOUBLE, MPI_MAX, 0, MPI_COMM_WORLD);
+      etime = MPI_Wtime();
+      /* end computation */
+
+      comptime = etime - stime;
+
+      if(_debug==1) printf("%d: comptime = %10.4f\n", rank, comptime);
+      
+      MPI_Reduce(&comptime, &max_comptime, 1, MPI_DOUBLE, MPI_MAX, 0, MPI_COMM_WORLD);
+
+      if(rank == 0) {
+          elapsed_time = max_comptime + max_iotime;
+          printf("<<Result (SUM) with normal read>>\n"
+                 "SUM              = %10.4f \n"
+                 "Computation time = %10.4f sec\n"
+                 "I/O time         = %10.4f sec\n"
+                 "total time       = %10.4f sec\n\n", 
+                 global_sum, max_comptime, max_iotime, elapsed_time);
+      }
+      
+      MPI_File_close(&fh);
+  }
 
   if(use_actsto == 1) {
+      memset(&status, 0xff, sizeof(MPI_Status));
+      offset = rank * nitem * type_size;
+#if 0
     /* MPI_MAX */
     MPI_File_open( comm, fname, MPI_MODE_RDWR, MPI_INFO_NULL, &fh );
@@ -221 +241 @@
     
     MPI_File_close(&fh);
-    
+#endif
     /* MPI_SUM */
     MPI_File_open( comm, fname, MPI_MODE_RDWR, MPI_INFO_NULL, &fh );
@@ -229 +249 @@
     etime = MPI_Wtime();
     elapsed_time = etime - stime;
-    printf ("sum=%lf (in %10.4f sec)\n", tmp[0], elapsed_time); 
+    printf ("<<Result with active storage>>\n"
+            "sum=%lf (in %10.4f sec)\n", tmp[0], elapsed_time); 
     
     MPI_File_close( &fh );

branches/as-branch/test/active-storage/test_kmeans.c

@@ -37 +37 @@
   MPI_Info info;
   float threshold = 0.0;
+  double stime, etime;
 
   /* for KMEANS */
@@ -118 +119 @@
     objects[i] = objects[i-1] + (numCoords);
 
-  
+  stime = MPI_Wtime(); 
   MPI_File_read_ex(fh, objects[0], (numObjs)*(numCoords),
                    MPI_FLOAT, MPI_KMEANS, &status);
 
+  etime = MPI_Wtime();
+  printf("%d: time =%10.4f\n", rank, etime-stime);
   //printf ("kmean=%lf\n", objects[0]);