log duration of tasks (#150)

lib/python/ray/worker.py

@@ -1,3 +1,4 @@
+import time
 import datetime
 import logging
 import os
@@ -177,9 +178,11 @@ def remote(arg_types, return_types, worker=global_worker):
     def func_executor(arguments):
       """This is what gets executed remotely on a worker after a remote function is scheduled by the scheduler."""
       logging.info("Calling function {}".format(func.__name__))
+      start_time = time.time()
       result = func(*arguments)
+      end_time = time.time()
       check_return_values(func_call, result) # throws an exception if result is invalid
-      logging.info("Finished executing function {}".format(func.__name__))
+      logging.info("Finished executing function {}, it took {} seconds".format(func.__name__, end_time - start_time))
       return result
     def func_call(*args, **kwargs):
       """This is what gets run immediately when a worker calls a remote function."""

src/objstore.cc

@@ -156,7 +156,7 @@ Status ObjStoreService::NotifyAlias(ServerContext* context, const NotifyAliasReq
 
 Status ObjStoreService::DeallocateObject(ServerContext* context, const DeallocateObjectRequest* request, AckReply* reply) {
   ObjRef canonical_objref = request->canonical_objref();
-  RAY_LOG(RAY_REFCOUNT, "Deallocating canonical_objref " << canonical_objref);
+  RAY_LOG(RAY_INFO, "Deallocating canonical_objref " << canonical_objref);
   std::lock_guard<std::mutex> memory_lock(memory_lock_);
   RAY_CHECK_EQ(memory_[canonical_objref].second, MemoryStatusType::READY, "Attempting to deallocate canonical_objref " << canonical_objref << ", but memory_[canonical_objref].second = " << memory_[canonical_objref].second);
   RAY_CHECK_LT(canonical_objref, memory_.size(), "Attempting to deallocate canonical_objref " << canonical_objref << ", but it is not in the objstore.");
@@ -294,6 +294,7 @@ ObjHandle ObjStoreService::alloc(ObjRef objref, size_t size) {
 
 void ObjStoreService::object_ready(ObjRef objref, size_t metadata_offset) {
   {
+    RAY_LOG(RAY_INFO, "Objref " << objref << " is ready.");
     std::lock_guard<std::mutex> memory_lock(memory_lock_);
     std::pair<ObjHandle, MemoryStatusType>& item = memory_[objref];
     RAY_CHECK_EQ(item.second, MemoryStatusType::NOT_READY, "A worker notified the object store that objref " << objref << " has been written to the object store, but memory_[objref].second != NOT_READY.");