SINGA-138 add clocks for forward and backward functions.

Makefile.am

@@ -99,7 +99,8 @@ SINGA_SRCS := src/driver.cc \
               src/utils/param.cc \
               src/utils/updater.cc \
               src/utils/blob.cc \
-              src/utils/image_transform.cc
+              src/utils/image_transform.cc \
+              src/utils/clock.cc
 
 SINGA_HDRS := include/singa.h \
 			  include/singa/utils/math_blob.h \
@@ -117,6 +118,7 @@ SINGA_HDRS := include/singa.h \
               include/utils/tinydir.h \
               include/utils/tokenizer.h \
               include/utils/image_transform.h \
+              include/utils/clock.h \
               include/server.h \
               include/worker.h \
               include/stub.h \

include/singa/utils/clock.h

@@ -0,0 +1,55 @@
+/************************************************************
+*
+* Licensed to the Apache Software Foundation (ASF) under one
+* or more contributor license agreements.  See the NOTICE file
+* distributed with this work for additional information
+* regarding copyright ownership.  The ASF licenses this file
+* to you under the Apache License, Version 2.0 (the
+* "License"); you may not use this file except in compliance
+* with the License.  You may obtain a copy of the License at
+*
+*   http://www.apache.org/licenses/LICENSE-2.0
+*
+* Unless required by applicable law or agreed to in writing,
+* software distributed under the License is distributed on an
+* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+* KIND, either express or implied.  See the License for the
+* specific language governing permissions and limitations
+* under the License.
+*
+*************************************************************/
+
+#ifndef _SINGA_UTILS_CLOCK_H_
+#define _SINGA_UTILS_CLOCK_H_
+
+#include <string>
+
+namespace singa {
+
+class Clock {
+ public:
+  Clock();
+
+  void Start();
+
+  double End();
+  double End(int iteration_num, std::string content);
+  void EndWithLog(std::string content);
+  void EndWithLog(int iteration_num, std::string content);
+
+  double Elapse();
+  double Elapse(int iteration_num, std::string content);
+  void ElapseWithLog(std::string content);
+  void ElapseWithLog(int iteration_num, std::string content);
+
+ protected:
+  int start_t = -1, end_t = -1;
+};
+
+
+}  // namespace singa
+
+
+
+
+#endif  // SINGA_UTILS_CLOCK_H_

src/utils/clock.cc

@@ -0,0 +1,92 @@
+/************************************************************
+*
+* Licensed to the Apache Software Foundation (ASF) under one
+* or more contributor license agreements.  See the NOTICE file
+* distributed with this work for additional information
+* regarding copyright ownership.  The ASF licenses this file
+* to you under the Apache License, Version 2.0 (the
+* "License"); you may not use this file except in compliance
+* with the License.  You may obtain a copy of the License at
+*
+*   http://www.apache.org/licenses/LICENSE-2.0
+*
+* Unless required by applicable law or agreed to in writing,
+* software distributed under the License is distributed on an
+* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+* KIND, either express or implied.  See the License for the
+* specific language governing permissions and limitations
+* under the License.
+*
+*************************************************************/
+
+#include "singa/utils/clock.h"
+
+#include <glog/logging.h>
+#include <cmath>
+#include <ctime>
+#include "singa/utils/cluster.h"
+#include "singa/utils/factory.h"
+#include "singa/utils/singleton.h"
+#include "singa/utils/context.h"
+
+namespace singa {
+
+Clock::Clock() {
+  start_t = clock();
+}
+
+
+
+void Clock::Start() {
+  start_t = clock();
+}
+
+double Clock::End() {
+  end_t = clock();
+  double runtime = (end_t-start_t)/static_cast<double>(CLOCKS_PER_SEC)*1000;
+  return runtime;
+}
+
+double Clock::End(int iteration_num, std::string content) {
+  end_t = clock();
+  double runtime = (end_t-start_t);
+  runtime = runtime/(static_cast<double>(CLOCKS_PER_SEC)*1000*iteration_num);
+  return runtime;
+}
+
+void Clock::EndWithLog(std::string content) {
+  double runtime = end();
+  DLOG(ERROR) << "Running time of " << content<< " is " << runtime << " ms";
+}
+
+void Clock::EndWithLog(int iteration_num, std::string content) {
+  double runtime = end(iteration_num, content);
+  DLOG(ERROR)<< "Average Running time of " << iteration_num;
+  DLOG(ERROR)<< " iterations in " << content << " is " << runtime << " ms";
+}
+
+double Clock::Elapse() {
+  end_t = clock();
+  double runtime = (end_t-start_t)/static_cast<double>(CLOCKS_PER_SEC)*1000;
+  return runtime;
+}
+
+double Clock::Elapse(int iteration_num, std::string content) {
+  end_t = clock();
+  double runtime = (end_t-start_t);
+  runtime = runtime/(static_cast<double>(CLOCKS_PER_SEC)*1000*iteration_num);
+  return runtime;
+}
+
+void Clock::ElapseWithLog(std::string content) {
+  double runtime = end();
+  DLOG(ERROR)<< "Running time of " <<content << " is " << runtime << " ms";
+}
+
+void Clock::ElapseWithLog(int iteration_num, std::string content) {
+  double runtime = end(iteration_num, content);
+  DLOG(ERROR) << "Average Running time of " << iteration_num;
+  DLOG(ERROR) << " iterations in " << content << " is " << runtime << " ms";
+}
+
+}  // namespace singa

src/worker.cc

@@ -30,13 +30,14 @@
 #include "singa/utils/singleton.h"
 #include "singa/utils/context.h"
 #include "singa/utils/math_blob.h"
+#include "singa/utils/clock.h"
 
 namespace singa {
 
 using std::string;
 
 Worker* Worker::Create(const AlgProto& conf) {
-  auto factory = Singleton<Factory<singa::Worker>>::Instance();
+  auto factory = Singleton<Factory<Worker>>::Instance();
   Worker* worker = nullptr;
   if (conf.has_user_alg())
     worker = factory->Create(conf.user_alg());
@@ -335,6 +336,8 @@ void BPWorker::TestOneBatch(int step, Phase phase, NeuralNet* net) {
 }
 
 void BPWorker::Forward(int step, Phase phase, NeuralNet* net) {
+  Clock c;
+  c.start();
   map<string, string> label;
   for (auto& layer : net->layers()) {
     if (layer->partition_id() == id_) {
@@ -355,9 +358,12 @@ void BPWorker::Forward(int step, Phase phase, NeuralNet* net) {
       + std::to_string(step) +"-loc" + std::to_string(id_) + ".json";
     WriteStringToTextFile(path, net->ToGraph(false).ToJson(label));
   }
+  c.endWithLog("BPWorker::Forward");
 }
 
 void BPWorker::Backward(int step, NeuralNet* net) {
+  Clock c;
+  c.start();
   map<string, string> label;
   auto& layers = net->layers();
   for (auto it = layers.rbegin(); it != layers.rend(); it++) {
@@ -375,10 +381,13 @@ void BPWorker::Backward(int step, NeuralNet* net) {
       + std::to_string(step) + "-loc" + std::to_string(id_) + ".json";
     WriteStringToTextFile(path, net->ToGraph(false).Reverse().ToJson(label));
   }
+  c.endWithLog("BPWorker::Backward");
 }
 
 /***************************BPTTWorker*********************************/
 void BPTTWorker::Forward(int step, Phase phase, NeuralNet* net) {
+  Clock c;
+  c.start();
   map<string, string> label;
   for (auto& layer : net->layers()) {
     if (layer->partition_id() == id_) {
@@ -425,9 +434,12 @@ void BPTTWorker::Forward(int step, Phase phase, NeuralNet* net) {
       + std::to_string(step) +"-loc" + std::to_string(id_) + ".json";
     WriteStringToTextFile(path, net->ToGraph(false).ToJson(label));
   }
+  c.endWithLog("BPTTWorker::Forward");
 }
 
 void BPTTWorker::Backward(int step, NeuralNet* net) {
+  Clock c;
+  c.start();
   map<string, string> label;
   auto& layers = net->layers();
   for (auto it = layers.rbegin(); it != layers.rend(); it++) {
@@ -449,6 +461,7 @@ void BPTTWorker::Backward(int step, NeuralNet* net) {
       + std::to_string(step) + "-loc" + std::to_string(id_) + ".json";
     WriteStringToTextFile(path, net->ToGraph(false).Reverse().ToJson(label));
   }
+  c.endWithLog("BPTTWorker::Backward");
 }
 void BPTTWorker::Display(int flag, const std::string& prefix, NeuralNet* net) {
   std::unordered_map<string, float> perf;