From 917e90a2e1be366fdc478a321accd96b79cb55f5 Mon Sep 17 00:00:00 2001 From: Sergio Date: Wed, 15 Oct 2014 15:35:01 -0700 Subject: [PATCH] Added timers for benchmarking --- src/caffe/layers/data_layer.cpp | 22 +++++++++++++++++++--- src/caffe/layers/image_data_layer.cpp | 13 +++++++++++++ src/caffe/layers/window_data_layer.cpp | 20 ++++++++++++++------ src/caffe/net.cpp | 7 +++++++ 4 files changed, 53 insertions(+), 9 deletions(-) diff --git a/src/caffe/layers/data_layer.cpp b/src/caffe/layers/data_layer.cpp index fcf9bb2..330381d 100644 --- a/src/caffe/layers/data_layer.cpp +++ b/src/caffe/layers/data_layer.cpp @@ -8,6 +8,7 @@ #include "caffe/dataset_factory.hpp" #include "caffe/layer.hpp" #include "caffe/proto/caffe.pb.h" +#include "caffe/util/benchmark.hpp" #include "caffe/util/io.hpp" #include "caffe/util/math_functions.hpp" #include "caffe/util/rng.hpp" @@ -47,6 +48,9 @@ void DataLayer::DataLayerSetUp(const vector*>& bottom, CHECK(iter_ != dataset_->end()); const Datum& datum = iter_->value; + if (DecodeDatum(datum)) { + LOG(INFO) << "Decoding Datum"; + } // image int crop_size = this->layer_param_.transform_param().crop_size(); if (crop_size > 0) { @@ -78,6 +82,8 @@ void DataLayer::DataLayerSetUp(const vector*>& bottom, // This function is used to create a thread that prefetches the data. template void DataLayer::InternalThreadEntry() { + Timer batch_timer; + batch_timer.Start(); CHECK(this->prefetch_data_.count()); CHECK(this->transformed_data_.count()); Dtype* top_data = this->prefetch_data_.mutable_cpu_data(); @@ -87,25 +93,35 @@ void DataLayer::InternalThreadEntry() { top_label = this->prefetch_label_.mutable_cpu_data(); } const int batch_size = this->layer_param_.data_param().batch_size(); - + float read_time = 0; + float trans_time = 0; + Timer timer; for (int item_id = 0; item_id < batch_size; ++item_id) { + timer.Start(); + // get a blob CHECK(iter_ != dataset_->end()); const Datum& datum = iter_->value; + cv::Mat cv_img = DecodeDatumToCVMat(datum); + read_time += timer.MilliSeconds(); + timer.Start(); // Apply data transformations (mirror, scale, crop...) int offset = this->prefetch_data_.offset(item_id); this->transformed_data_.set_cpu_data(top_data + offset); - this->data_transformer_.Transform(datum, &(this->transformed_data_)); + this->data_transformer_.Transform(cv_img, &(this->transformed_data_)); if (this->output_labels_) { top_label[item_id] = datum.label(); } - + trans_time += timer.MilliSeconds(); // go to the next iter ++iter_; if (iter_ == dataset_->end()) { iter_ = dataset_->begin(); } } + DLOG(INFO) << "Prefetch batch: " << batch_timer.MilliSeconds() << "ms."; + DLOG(INFO) << "Read time: " << read_time << "ms."; + DLOG(INFO) << "Transform time: " << trans_time << "ms."; } INSTANTIATE_CLASS(DataLayer); diff --git a/src/caffe/layers/image_data_layer.cpp b/src/caffe/layers/image_data_layer.cpp index 2085df2..6749311 100644 --- a/src/caffe/layers/image_data_layer.cpp +++ b/src/caffe/layers/image_data_layer.cpp @@ -6,6 +6,7 @@ #include "caffe/data_layers.hpp" #include "caffe/layer.hpp" +#include "caffe/util/benchmark.hpp" #include "caffe/util/io.hpp" #include "caffe/util/math_functions.hpp" #include "caffe/util/rng.hpp" @@ -91,6 +92,8 @@ void ImageDataLayer::ShuffleImages() { // This function is used to create a thread that prefetches the data. template void ImageDataLayer::InternalThreadEntry() { + Timer batch_timer; + batch_timer.Start(); CHECK(this->prefetch_data_.count()); CHECK(this->transformed_data_.count()); Dtype* top_data = this->prefetch_data_.mutable_cpu_data(); @@ -103,18 +106,25 @@ void ImageDataLayer::InternalThreadEntry() { // datum scales const int lines_size = lines_.size(); + float read_time = 0; + float trans_time = 0; + Timer timer; for (int item_id = 0; item_id < batch_size; ++item_id) { // get a blob + timer.Start(); CHECK_GT(lines_size, lines_id_); cv::Mat cv_img = ReadImageToCVMat(lines_[lines_id_].first, new_height, new_width, is_color); if (!cv_img.data) { continue; } + read_time += timer.MilliSeconds(); + timer.Start(); // Apply transformations (mirror, crop...) to the image int offset = this->prefetch_data_.offset(item_id); this->transformed_data_.set_cpu_data(top_data + offset); this->data_transformer_.Transform(cv_img, &(this->transformed_data_)); + trans_time += timer.MilliSeconds(); top_label[item_id] = lines_[lines_id_].second; // go to the next iter @@ -128,6 +138,9 @@ void ImageDataLayer::InternalThreadEntry() { } } } + DLOG(INFO) << "Prefetch batch: " << batch_timer.MilliSeconds() << "ms."; + DLOG(INFO) << "Read time: " << read_time << "ms."; + DLOG(INFO) << "Transform time: " << trans_time << "ms."; } INSTANTIATE_CLASS(ImageDataLayer); diff --git a/src/caffe/layers/window_data_layer.cpp b/src/caffe/layers/window_data_layer.cpp index 529c3b4..47e0fb2 100644 --- a/src/caffe/layers/window_data_layer.cpp +++ b/src/caffe/layers/window_data_layer.cpp @@ -13,6 +13,7 @@ #include "caffe/common.hpp" #include "caffe/data_layers.hpp" #include "caffe/layer.hpp" +#include "caffe/util/benchmark.hpp" #include "caffe/util/io.hpp" #include "caffe/util/math_functions.hpp" #include "caffe/util/rng.hpp" @@ -192,7 +193,8 @@ template void WindowDataLayer::InternalThreadEntry() { // At each iteration, sample N windows where N*p are foreground (object) // windows and N*(1-p) are background (non-object) windows - + Timer batch_timer; + batch_timer.Start(); Dtype* top_data = this->prefetch_data_.mutable_cpu_data(); Dtype* top_label = this->prefetch_label_.mutable_cpu_data(); const Dtype scale = this->layer_param_.window_data_param().scale(); @@ -219,19 +221,20 @@ void WindowDataLayer::InternalThreadEntry() { const int num_samples[2] = { batch_size - num_fg, num_fg }; int item_id = 0; + float read_time = 0; + float trans_time = 0; + Timer timer; // sample from bg set then fg set for (int is_fg = 0; is_fg < 2; ++is_fg) { for (int dummy = 0; dummy < num_samples[is_fg]; ++dummy) { // sample a window + timer.Start(); const unsigned int rand_index = PrefetchRand(); vector window = (is_fg) ? fg_windows_[rand_index % fg_windows_.size()] : bg_windows_[rand_index % bg_windows_.size()]; - bool do_mirror = false; - if (mirror && PrefetchRand() % 2) { - do_mirror = true; - } + bool do_mirror = mirror && PrefetchRand() % 2; // load the image containing the window pair > image = @@ -242,6 +245,8 @@ void WindowDataLayer::InternalThreadEntry() { LOG(ERROR) << "Could not open or find file " << image.first; return; } + read_time += timer.MilliSeconds(); + timer.Start(); const int channels = cv_img.channels(); // crop window out of image and warp it @@ -359,7 +364,7 @@ void WindowDataLayer::InternalThreadEntry() { } } } - + trans_time += timer.MilliSeconds(); // get window label top_label[item_id] = window[WindowDataLayer::LABEL]; @@ -399,6 +404,9 @@ void WindowDataLayer::InternalThreadEntry() { item_id++; } } + DLOG(INFO) << "Prefetch batch: " << batch_timer.MilliSeconds() << "ms."; + DLOG(INFO) << "Read time: " << read_time << "ms."; + DLOG(INFO) << "Transform time: " << trans_time << "ms."; } INSTANTIATE_CLASS(WindowDataLayer); diff --git a/src/caffe/net.cpp b/src/caffe/net.cpp index 21ab15f..5b7152e 100644 --- a/src/caffe/net.cpp +++ b/src/caffe/net.cpp @@ -9,6 +9,7 @@ #include "caffe/layer.hpp" #include "caffe/net.hpp" #include "caffe/proto/caffe.pb.h" +#include "caffe/util/benchmark.hpp" #include "caffe/util/insert_splits.hpp" #include "caffe/util/io.hpp" #include "caffe/util/math_functions.hpp" @@ -499,6 +500,8 @@ void Net::GetLearningRateAndWeightDecay() { template Dtype Net::ForwardFromTo(int start, int end) { + Timer timer; + timer.Start(); CHECK_GE(start, 0); CHECK_LT(end, layers_.size()); Dtype loss = 0; @@ -509,6 +512,7 @@ Dtype Net::ForwardFromTo(int start, int end) { loss += layer_loss; if (debug_info_) { ForwardDebugInfo(i); } } + LOG(INFO) << "Forward time: " << timer.MilliSeconds() << "ms."; return loss; } @@ -565,6 +569,8 @@ string Net::Forward(const string& input_blob_protos, Dtype* loss) { template void Net::BackwardFromTo(int start, int end) { + Timer timer; + timer.Start(); CHECK_GE(end, 0); CHECK_LT(start, layers_.size()); for (int i = start; i >= end; --i) { @@ -574,6 +580,7 @@ void Net::BackwardFromTo(int start, int end) { if (debug_info_) { BackwardDebugInfo(i); } } } + LOG(INFO) << "Backward time: " << timer.MilliSeconds() << "ms."; } template -- 2.7.4