Add profile option using clock()

This makes the service provider record the timestamps at certain points in
each request, and return that information to the user. Still need to get
the data processing scripts adapted.

9 files changed, 146 insertions, 31 deletions

diff --git a/client.c b/client.c
index e3e1526..5fc8f82 100644
--- a/client.c
+++ b/client.c
@@ -30,11 +30,12 @@
 #include <sys/socket.h>
 #include <sys/un.h>
 
+#include <assert.h>
 #include <signal.h>
+#include <stdbool.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <unistd.h>
-#include <assert.h>
 
 static const char *socket_path = "socket";
 static const char *parse_args_fail = NULL;
@@ -42,7 +43,7 @@ static const char *userkey = NULL;
 static uint64_t user_id = 0;
 static struct user_request cl_request;
 static struct iomt *new_acl = NULL;
-const char *buildcode_path = NULL, *compose_path = NULL, *image_path = NULL, *file_key = NULL;
+static const char *buildcode_path = NULL, *compose_path = NULL, *image_path = NULL, *file_key = NULL;
 
 int compare_tuple(const void *p1, const void *p2)
 {
@@ -184,6 +185,10 @@ bool parse_args(int argc, char *argv[])
             print_usage(argv[0]);
             exit(1);
         }
+        else if(!strcmp(arg, "-p") || !strcmp(arg, "--profile"))
+        {
+            cl_request.profile = true;
+        }
         else if(!strcmp(arg, "create"))
         {
             if(cl_request.type != USERREQ_NONE)
@@ -356,7 +361,7 @@ static struct tm_request verify_and_sign(int fd, const struct user_request *req,
         return req_null;
     }
 
-    printf("Signing request\n");
+    //printf("Signing request\n");
     hash_t hmac = hmac_sha256(&tmr, sizeof(tmr), userkey, strlen(userkey));
     write(fd, &hmac, sizeof(hmac));
 
@@ -372,6 +377,13 @@ static bool verify_sp_ack(int fd, const struct tm_request *tmr)
     return verify_ack(tmr, userkey, strlen(userkey), hmac);
 }
 
+/* hack to avoid copy-pasta below */
+static void read_profile(int fd, struct server_profile *profile_out)
+{
+    if(profile_out)
+        recv(fd, profile_out, sizeof(*profile_out), MSG_WAITALL);
+}
+
 /* In case of modifcation or file creation, returns true on successful
  * completion of request, as acknowledged by module. In case of info
  * retrieval, returns true if version info is verified by module. The
@@ -389,7 +401,8 @@ bool exec_request(int fd, const struct user_request *req,
                   void **composefile, size_t *cf_len_out,    /* RETRIEVE_FILE only */
                   hash_t *secret_out,                        /* RETRIEVE_FILE only */
                   void **file_contents_out,                  /* RETRIEVE_FILE only */
-                  size_t *file_len)                          /* RETRIEVE_FILE only */
+                  size_t *file_len,                          /* RETRIEVE_FILE only */
+                  struct server_profile *profile_out)        /* profile=true only */
 {
     write(fd, req, sizeof(*req));
     /* write additional data */
@@ -413,6 +426,8 @@ bool exec_request(int fd, const struct user_request *req,
         break;
     }
 
+    bool success = true;
+
     switch(req->type)
     {
     case CREATE_FILE:
@@ -438,7 +453,13 @@ bool exec_request(int fd, const struct user_request *req,
         struct tm_request tmr = verify_and_sign(fd, req, val);
         if(tmreq_out)
             *tmreq_out = tmr;
-        return verify_sp_ack(fd, &tmr);
+
+        success = verify_sp_ack(fd, &tmr);
+
+        if(req->profile)
+            read_profile(fd, profile_out);
+
+        break;
     }
     case RETRIEVE_INFO:
     {
@@ -458,10 +479,15 @@ bool exec_request(int fd, const struct user_request *req,
             }
 
             *verinfo_out = verinfo;
-            return true;
+
+            success = true;
         }
+        else
+            success = false;
 
-        return false;
+        if(req->profile)
+            read_profile(fd, profile_out);
+        break;
     }
     case RETRIEVE_FILE:
     {
@@ -483,11 +509,18 @@ bool exec_request(int fd, const struct user_request *req,
         *buildcode = deserialize_file(fd, bc_len_out);
         *composefile = deserialize_file(fd, cf_len_out);
 
-        return *file_contents_out != NULL;
+        if(req->profile)
+            read_profile(fd, profile_out);
+
+        success = *file_contents_out != NULL;
+
+        break;
     }
     default:
         assert(false);
     }
+
+    return success;
 }
 
 /* set version = 0 to get latest version */
@@ -517,6 +550,7 @@ struct version_info request_verinfo(int fd, uint64_t user_id,
                            NULL, NULL,
                            NULL,
                            NULL,
+                           NULL,
                            NULL);
     if(rc)
         return verinfo;
@@ -550,6 +584,25 @@ int connect_to_service(const char *sockpath)
     return fd;
 }
 
+void prof_dump(struct server_profile *profile)
+{
+    //for(int i = 0; i < profile->n_times; ++i)
+    //fprintf(stderr, "%s ", profile->labels[i]);
+    //fprintf(stderr, "\n");
+
+    clock_t sum = 0;
+
+    /* TODO: use partial sums? */
+    for(int i = 0; i < profile->n_times; ++i)
+    {
+        fprintf(stderr, "%ld ", profile->times[i] - profile->times[i - 1]);
+
+        if(i > 0)
+            sum += profile->times[i] - profile->times[i - 1];
+    }
+    fprintf(stderr, "%ld\n", sum);
+}
+
 bool server_request(const char *sockpath,
                     const char *user_key, uint64_t user_id,
                     struct user_request req,
@@ -620,6 +673,7 @@ bool server_request(const char *sockpath,
 
     struct version_info verinfo;
     struct tm_request tmreq;
+    struct server_profile profile;
 
     int fd = connect_to_service(sockpath);
 
@@ -641,7 +695,8 @@ bool server_request(const char *sockpath,
                                 req.type == RETRIEVE_FILE ? &cf_len : NULL,
                                 req.type == RETRIEVE_FILE ? &secret : NULL,
                                 req.type == RETRIEVE_FILE ? &file_contents : NULL,
-                                req.type == RETRIEVE_FILE ? &file_len : NULL);
+                                req.type == RETRIEVE_FILE ? &file_len : NULL,
+                                req.profile ? &profile : NULL);
 
     close(fd);
 
@@ -651,7 +706,7 @@ bool server_request(const char *sockpath,
            "\033[31;1mfailed\033[0m");
 
     if(!success)
-        return false;
+        return success;
 
     switch(req.type)
     {
@@ -699,7 +754,7 @@ bool server_request(const char *sockpath,
                                                       0);
         close(fd);
 
-        bool success = hash_equals(lambda, verinfo.lambda);
+        success = hash_equals(lambda, verinfo.lambda);
 
         if(!success)
         {
@@ -709,13 +764,19 @@ bool server_request(const char *sockpath,
         else
             printf("Successfully verifed integrity of file.\n");
 
-        return success;
+        break;
     }
     default:
         break;
     }
 
-    return true;
+    if(req.profile)
+    {
+        /* dump to stderr */
+        prof_dump(&profile);
+    }
+
+    return success;
 }
 
 int main(int argc, char *argv[]) {
diff --git a/service_provider.c b/service_provider.c
index ebb81c1..5fc5f7d 100644
--- a/service_provider.c
+++ b/service_provider.c
@@ -69,6 +69,8 @@ struct service_provider {
 
     sqlite3_stmt *lookup_record, *insert_record, *update_record,
         *insert_version, *count_versions, *lookup_version, *find_empty;
+
+    struct server_profile profile;
 };
 
 /* Generate an EQ certificate for inserting a placeholder with index
@@ -405,9 +407,22 @@ void sp_free(struct service_provider *sp)
     }
 }
 
-/* TODO: pre-compile these statements */
+static void prof_reset(struct server_profile *prof)
+{
+    memset(prof, 0, sizeof(*prof));
+}
+
+static void prof_add(struct server_profile *prof, const char *label)
+{
+    if(prof->n_times < MAX_TIMES)
+    {
+        prof->times[prof->n_times] = clock();
+        strcpy(prof->labels[prof->n_times], label);
+
+        prof->n_times++;
+    }
+}
 
-/* linear search for record given idx */
 static struct file_record *lookup_record(struct service_provider *sp, uint64_t idx)
 {
     sqlite3_stmt *st = sp->lookup_record;
@@ -740,7 +755,11 @@ struct tm_request sp_createfile(struct service_provider *sp,
 
     if(sp->n_placeholders > 0)
     {
+        /* We already have a placeholder in the tree. Find it (this
+         * should only happen once in the lifetime of the IOMT, when
+         * it is first created). */
         i = find_empty_slot(sp);
+
         if(i == (uint64_t) -1)
         {
             assert(false); /* shouldn't happen */
@@ -786,6 +805,8 @@ struct tm_request sp_createfile(struct service_provider *sp,
         sp->n_placeholders++;
     }
 
+    prof_add(&sp->profile, "finish_placeholder_insert");
+
     printf("Allocated leaf index %lu\n", i);
 
     int *file_orders;
@@ -808,6 +829,8 @@ struct tm_request sp_createfile(struct service_provider *sp,
     hash_t req_hmac = sign_request(userdata, &req);
     hash_t fr_hmac;
 
+    prof_add(&sp->profile, "finish_populate_request");
+
     struct tm_cert fr_cert = sp_request(sp,
                                         &req, req_hmac,
                                         &fr_hmac,
@@ -818,6 +841,9 @@ struct tm_request sp_createfile(struct service_provider *sp,
                                         NULL, 0,
                                         NULL, 0,
                                         acl);
+
+    prof_add(&sp->profile, "finish_exec_request");
+
     sp->n_placeholders--;
 
     /* sp_request() has made a copy of the ACL */
@@ -1144,6 +1170,12 @@ static void sp_handle_client(struct service_provider *sp, int cl)
 
     hash_t ack_hmac = hash_null;
 
+    if(user_req.profile)
+        prof_reset(&sp->profile);
+
+    /* logging is unconditional */
+    prof_add(&sp->profile, "start");
+
     switch(user_req.type)
     {
     case CREATE_FILE:
@@ -1266,6 +1298,11 @@ static void sp_handle_client(struct service_provider *sp, int cl)
         exit(1);
     }
     }
+
+    prof_add(&sp->profile, "end");
+
+    if(user_req.profile)
+        write(cl, &sp->profile, sizeof(sp->profile));
 }
 
 /* will be called by main.c's signal handler to save the module's
diff --git a/service_provider.h b/service_provider.h
index 97cf37e..f20e5df 100644
--- a/service_provider.h
+++ b/service_provider.h
@@ -4,6 +4,8 @@
 #ifndef CSAA_SERVICE_PROVIDER_H
 #define CSAA_SERVICE_PROVIDER_H
 
+#include <time.h>
+
 #include "crypto.h"
 #include "trusted_module.h"
 
@@ -66,8 +68,22 @@ struct user_request {
              * key (which the client can verify themselves) */
         } retrieve;
     };
+
+    bool profile; /* if true, service will send a server_profile
+                   * struct after the request response */
 } __attribute__((packed));
 
+#define MAX_TIMES 10
+#define MAX_LABEL 40
+
+/* this struct records a series of clock() times, and labels for them */
+struct server_profile {
+    clock_t times[MAX_TIMES];
+    char labels[MAX_TIMES][MAX_LABEL];
+
+    int n_times;
+};
+
 #ifndef CLIENT
 struct service_provider *sp_new(const void *key,
                                 size_t keylen,
diff --git a/testall.sh b/testall.sh
index e2c584c..600ffe2 100755
--- a/testall.sh
+++ b/testall.sh
@@ -14,12 +14,12 @@ rm files -rf
 ./server $1 csaa.db --overwrite > /dev/null &
 pid=$!
 sleep .2
-/usr/bin/time -v ./testcreate.sh ./client $runs_create
-/usr/bin/time -v ./testmodify.sh ./client $runs_test 1
-/usr/bin/time -v ./testretrieve.sh ./client $runs_test 1
-/usr/bin/time -v ./testmodifyenc.sh ./client $runs_test 1
+./testcreate.sh ./client $runs_create
+./testmodify.sh ./client $runs_test 1
+./testretrieve.sh ./client $runs_test 1
+./testmodifyenc.sh ./client $runs_test 1
 
 echo "Encrypted retrieve: "
-/usr/bin/time -v ./testretrieve.sh ./client $runs_test 1
+./testretrieve.sh ./client $runs_test 1
 kill -SIGINT $!
 rm csaa.db
diff --git a/testall_preinit.sh b/testall_preinit.sh
index 4a061b5..bf590db 100755
--- a/testall_preinit.sh
+++ b/testall_preinit.sh
@@ -9,24 +9,25 @@ logleaves=$1
 runs_test=$2
 
 echo "Initializing..."
-rm files -rf
+rm files csaa.db module_state -rf
 
 cp databases/csaa_$logleaves.db csaa.db
 cp databases/state_$logleaves module_state
-chmod 644 csaa.db
+
+chmod 644 csaa.db module_state
 
 start_id=$(echo "2^$1 - $runs_test" | bc)
 
 ./server $1 csaa.db > /dev/null &
 pid=$!
 sleep .2
-/usr/bin/time -v ./testcreate.sh ./client $runs_test
-/usr/bin/time -v ./testmodify.sh ./client $runs_test $start_id
-/usr/bin/time -v ./testretrieve.sh ./client $runs_test $start_id
-/usr/bin/time -v ./testmodifyenc.sh ./client $runs_test $start_id
+./testcreate.sh ./client $runs_test
+./testmodify.sh ./client $runs_test $start_id
+./testretrieve.sh ./client $runs_test $start_id
+./testmodifyenc.sh ./client $runs_test $start_id
 
 echo "Encrypted retrieve: "
-/usr/bin/time -v ./testretrieve.sh ./client $runs_test $start_id
+./testretrieve.sh ./client $runs_test $start_id
 
 kill -SIGINT $!
 rm csaa.db module_state
diff --git a/testcreate.sh b/testcreate.sh
index 3e3ca21..57b5781 100755
--- a/testcreate.sh
+++ b/testcreate.sh
@@ -2,7 +2,7 @@
 echo "Create:"
 for i in $(seq 1 $2)
 do
-    $1 -u 1 -k a create > /dev/null
+    $1 -u 1 -k a create -p > /dev/null
     if [[ $? -ne 0 ]]
     then
         echo "Request failed!"
diff --git a/testmodify.sh b/testmodify.sh
index 2762196..69800f8 100755
--- a/testmodify.sh
+++ b/testmodify.sh
@@ -6,7 +6,7 @@ stop=$(echo "$3+$2" | bc)
 
 for i in $(seq $3 $stop)
 do
-    $1 -u 1 -k a modifyfile -f $i -i container1/hello-world.tar > /dev/null
+    $1 -u 1 -k a modifyfile -f $i -i container1/hello-world.tar -p > /dev/null
     if [[ $? -ne 0 ]]
     then
         echo "Request failed!"
diff --git a/testmodifyenc.sh b/testmodifyenc.sh
index 4c4ae4f..5a3b10c 100755
--- a/testmodifyenc.sh
+++ b/testmodifyenc.sh
@@ -5,7 +5,7 @@ stop=$(echo "$3+$2" | bc)
 
 for i in $(seq $3 $stop)
 do
-    $1 -u 1 -k a modifyfile -e -f $i -i container1/hello-world.tar > /dev/null
+    $1 -u 1 -k a modifyfile -e -f $i -i container1/hello-world.tar -p > /dev/null
     if [[ $? -ne 0 ]]
     then
         echo "Request failed!"
diff --git a/testretrieve.sh b/testretrieve.sh
index f0db543..9a98f3f 100755
--- a/testretrieve.sh
+++ b/testretrieve.sh
@@ -6,7 +6,7 @@ stop=$(echo "$3+$2" | bc)
 
 for i in $(seq $3 $stop)
 do
-    $1 -u 1 -k a retrievefile -f $i -o out > /dev/null
+    $1 -u 1 -k a retrievefile -f $i -o out -p > /dev/null
     if [[ $? -ne 0 ]]
     then
         echo "Request failed!"