Log profiling information from worker. (#178)

* Log timing events on workers.

* Have workers log to the event log through the local scheduler.

* Fixes and address comments.

* bug fix

* styling

src/common/Makefile

@@ -4,7 +4,7 @@ BUILD = build
 
 all: hiredis redis redismodule $(BUILD)/libcommon.a
 
-$(BUILD)/libcommon.a: event_loop.o common.o task.o io.o net.o state/redis.o state/table.o state/object_table.o state/task_table.o state/db_client_table.o state/local_scheduler_table.o thirdparty/ae/ae.o thirdparty/sha256.o
+$(BUILD)/libcommon.a: event_loop.o common.o task.o io.o net.o logging.o state/redis.o state/table.o state/object_table.o state/task_table.o state/db_client_table.o state/local_scheduler_table.o thirdparty/ae/ae.o thirdparty/sha256.o
 	ar rcs $@ $^
 
 $(BUILD)/common_tests: test/common_tests.c $(BUILD)/libcommon.a

src/common/lib/python/common_extension.c

@@ -74,6 +74,14 @@ static PyObject *PyObjectID_id(PyObject *self) {
                                    sizeof(s->object_id.id));
 }
 
+static PyObject *PyObjectID_hex(PyObject *self) {
+  PyObjectID *s = (PyObjectID *) self;
+  char hex_id[ID_STRING_SIZE];
+  object_id_to_string(s->object_id, hex_id, ID_STRING_SIZE);
+  PyObject *result = PyUnicode_FromString(hex_id);
+  return result;
+}
+
 static PyObject *PyObjectID_richcompare(PyObjectID *self,
                                         PyObject *other,
                                         int op) {
@@ -140,6 +148,8 @@ static PyObject *PyObjectID___reduce__(PyObjectID *self) {
 static PyMethodDef PyObjectID_methods[] = {
     {"id", (PyCFunction) PyObjectID_id, METH_NOARGS,
      "Return the hash associated with this ObjectID"},
+    {"hex", (PyCFunction) PyObjectID_hex, METH_NOARGS,
+     "Return the object ID as a string in hex."},
     {"__reduce__", (PyCFunction) PyObjectID___reduce__, METH_NOARGS,
      "Say how to pickle this ObjectID. This raises an exception to prevent"
      "object IDs from being serialized."},

src/common/logging.c

@@ -82,3 +82,15 @@ void ray_log(ray_logger *logger,
   utstring_free(formatted_message);
   utstring_free(timestamp);
 }
+
+void ray_log_event(db_handle *db,
+                   uint8_t *key,
+                   int64_t key_length,
+                   uint8_t *value,
+                   int64_t value_length) {
+  int status = redisAsyncCommand(db->context, NULL, NULL, "RPUSH %b %b", key,
+                                 key_length, value, value_length);
+  if ((status == REDIS_ERR) || db->context->err) {
+    LOG_REDIS_DEBUG(db->context, "error while logging message to event log");
+  }
+}

src/common/logging.h

@@ -13,6 +13,8 @@
 #define RAY_OBJECT "OBJECT"
 #define RAY_TASK "TASK"
 
+#include "state/db.h"
+
 typedef struct ray_logger_impl ray_logger;
 
 /* Initialize a Ray logger for the given client type and logging level. If the
@@ -36,4 +38,20 @@ void ray_log(ray_logger *logger,
              const char *event_type,
              const char *message);
 
-#endif
+/**
+ * Log an event to the event log.
+ *
+ * @param db The database handle.
+ * @param key The key in Redis to store the event in.
+ * @param key_length The length of the key.
+ * @param value The value to log.
+ * @param value_length The length of the value.
+ * @return Void.
+ */
+void ray_log_event(db_handle *db,
+                   uint8_t *key,
+                   int64_t key_length,
+                   uint8_t *value,
+                   int64_t value_length);
+
+#endif /* LOGGING_H */

src/photon/photon.h

@@ -25,6 +25,8 @@ enum photon_message_type {
   EXECUTE_TASK,
   /** Reconstruct a possibly lost object. */
   RECONSTRUCT_OBJECT,
+  /** Log a message to the event table. */
+  EVENT_LOG_MESSAGE,
 };
 
 // clang-format off

src/photon/photon_client.c

@@ -15,6 +15,28 @@ void photon_disconnect(photon_conn *conn) {
   free(conn);
 }
 
+void photon_log_event(photon_conn *conn,
+                      uint8_t *key,
+                      int64_t key_length,
+                      uint8_t *value,
+                      int64_t value_length) {
+  int64_t message_length =
+      sizeof(key_length) + sizeof(value_length) + key_length + value_length;
+  uint8_t *message = malloc(message_length);
+  int64_t offset = 0;
+  memcpy(&message[offset], &key_length, sizeof(key_length));
+  offset += sizeof(key_length);
+  memcpy(&message[offset], &value_length, sizeof(value_length));
+  offset += sizeof(value_length);
+  memcpy(&message[offset], key, key_length);
+  offset += key_length;
+  memcpy(&message[offset], value, value_length);
+  offset += value_length;
+  CHECK(offset == message_length);
+  write_message(conn->conn, EVENT_LOG_MESSAGE, message_length, message);
+  free(message);
+}
+
 void photon_submit(photon_conn *conn, task_spec *task) {
   write_message(conn->conn, SUBMIT_TASK, task_spec_size(task),
                 (uint8_t *) task);

src/photon/photon_client.h

@@ -35,6 +35,25 @@ void photon_disconnect(photon_conn *conn);
  */
 void photon_submit(photon_conn *conn, task_spec *task);
 
+/**
+ * Log an event to the event log. This will call RPUSH key value. We use RPUSH
+ * instead of SET so that it is possible to flush the log multiple times with
+ * the same key (for example the key might be shared across logging calls in the
+ * same task on a worker).
+ *
+ * @param conn The connection information.
+ * @param key The key to store the event in.
+ * @param key_length The length of the key.
+ * @param value The value to store.
+ * @param value_length The length of the value.
+ * @return Void.
+ */
+void photon_log_event(photon_conn *conn,
+                      uint8_t *key,
+                      int64_t key_length,
+                      uint8_t *value,
+                      int64_t value_length);
+
 /**
  * Get next task for this client. This will block until the scheduler assigns
  * a task to this worker. This allocates and returns a task, and so the task

src/photon/photon_extension.c

@@ -62,6 +62,21 @@ static PyObject *PyPhotonClient_reconstruct_object(PyObject *self,
   Py_RETURN_NONE;
 }
 
+static PyObject *PyPhotonClient_log_event(PyObject *self, PyObject *args) {
+  const char *key;
+  int key_length;
+  const char *value;
+  int value_length;
+  if (!PyArg_ParseTuple(args, "s#s#", &key, &key_length, &value,
+                        &value_length)) {
+    return NULL;
+  }
+  photon_log_event(((PyPhotonClient *) self)->photon_connection,
+                   (uint8_t *) key, key_length, (uint8_t *) value,
+                   value_length);
+  Py_RETURN_NONE;
+}
+
 static PyMethodDef PyPhotonClient_methods[] = {
     {"submit", (PyCFunction) PyPhotonClient_submit, METH_VARARGS,
      "Submit a task to the local scheduler."},
@@ -69,6 +84,8 @@ static PyMethodDef PyPhotonClient_methods[] = {
      "Get a task from the local scheduler."},
     {"reconstruct_object", (PyCFunction) PyPhotonClient_reconstruct_object,
      METH_VARARGS, "Ask the local scheduler to reconstruct an object."},
+    {"log_event", (PyCFunction) PyPhotonClient_log_event, METH_VARARGS,
+     "Log an event to the event log through the local scheduler."},
     {NULL} /* Sentinel */
 };
 

src/photon/photon_scheduler.c

@@ -9,6 +9,7 @@
 #include "common.h"
 #include "event_loop.h"
 #include "io.h"
+#include "logging.h"
 #include "object_info.h"
 #include "photon.h"
 #include "photon_scheduler.h"
@@ -221,7 +222,7 @@ void process_message(event_loop *loop,
   local_scheduler_state *state = context;
 
   int64_t type;
-  read_buffer(client_sock, &type, state->input_buffer);
+  int64_t length = read_buffer(client_sock, &type, state->input_buffer);
 
   LOG_DEBUG("New event of type %" PRId64, type);
 
@@ -232,6 +233,30 @@ void process_message(event_loop *loop,
   } break;
   case TASK_DONE: {
   } break;
+  case EVENT_LOG_MESSAGE: {
+    /* Parse the message. TODO(rkn): Redo this using flatbuffers to serialize
+     * the message. */
+    uint8_t *message = (uint8_t *) utarray_front(state->input_buffer);
+    int64_t offset = 0;
+    int64_t key_length;
+    memcpy(&key_length, &message[offset], sizeof(key_length));
+    offset += sizeof(key_length);
+    int64_t value_length;
+    memcpy(&value_length, &message[offset], sizeof(value_length));
+    offset += sizeof(value_length);
+    uint8_t *key = malloc(key_length);
+    memcpy(key, &message[offset], key_length);
+    offset += key_length;
+    uint8_t *value = malloc(value_length);
+    memcpy(value, &message[offset], value_length);
+    offset += value_length;
+    CHECK(offset == length);
+    if (state->db != NULL) {
+      ray_log_event(state->db, key, key_length, value, value_length);
+    }
+    free(key);
+    free(value);
+  } break;
   case GET_TASK: {
     worker_index *wi;
     HASH_FIND_INT(state->worker_index, &client_sock, wi);