From 7d5420aa5ec485ce9cb3a466e50e421d46546ef7 Mon Sep 17 00:00:00 2001 From: Keisuke Kuroyanagi Date: Thu, 30 Oct 2014 18:15:30 +0900 Subject: [PATCH] Make profiler use getTimeInMicroSec(). Bug: 17797064 Change-Id: Ie992c9454edfc3bf93d5ea367c3a4427b513a205 --- ...oid_inputmethod_latin_BinaryDictionary.cpp | 8 +- native/jni/src/defines.h | 67 +-------------- native/jni/src/suggest/core/suggest.cpp | 16 ++-- native/jni/src/utils/profiler.h | 86 +++++++++++++++++++ 4 files changed, 100 insertions(+), 77 deletions(-) create mode 100644 native/jni/src/utils/profiler.h diff --git a/native/jni/com_android_inputmethod_latin_BinaryDictionary.cpp b/native/jni/com_android_inputmethod_latin_BinaryDictionary.cpp index 118f600bb..697ebca3b 100644 --- a/native/jni/com_android_inputmethod_latin_BinaryDictionary.cpp +++ b/native/jni/com_android_inputmethod_latin_BinaryDictionary.cpp @@ -35,6 +35,7 @@ #include "utils/int_array_view.h" #include "utils/jni_data_utils.h" #include "utils/log_utils.h" +#include "utils/profiler.h" #include "utils/time_keeper.h" namespace latinime { @@ -43,8 +44,8 @@ class ProximityInfo; static jlong latinime_BinaryDictionary_open(JNIEnv *env, jclass clazz, jstring sourceDir, jlong dictOffset, jlong dictSize, jboolean isUpdatable) { - PROF_OPEN; - PROF_START(66); + PROF_INIT; + PROF_TIMER_START(66); const jsize sourceDirUtf8Length = env->GetStringUTFLength(sourceDir); if (sourceDirUtf8Length <= 0) { AKLOGE("DICT: Can't get sourceDir string"); @@ -63,8 +64,7 @@ static jlong latinime_BinaryDictionary_open(JNIEnv *env, jclass clazz, jstring s Dictionary *const dictionary = new Dictionary(env, std::move(dictionaryStructureWithBufferPolicy)); - PROF_END(66); - PROF_CLOSE; + PROF_TIMER_END(66); return reinterpret_cast(dictionary); } diff --git a/native/jni/src/defines.h b/native/jni/src/defines.h index 885118524..0e67b4d5a 100644 --- a/native/jni/src/defines.h +++ b/native/jni/src/defines.h @@ -23,10 +23,10 @@ #define AK_FORCE_INLINE inline #endif // __GNUC__ -#if defined(FLAG_DO_PROFILE) || defined(FLAG_DBG) +#if defined(FLAG_DBG) #undef AK_FORCE_INLINE #define AK_FORCE_INLINE inline -#endif // defined(FLAG_DO_PROFILE) || defined(FLAG_DBG) +#endif // defined(FLAG_DBG) // Must be equal to Constants.Dictionary.MAX_WORD_LENGTH in Java #define MAX_WORD_LENGTH 48 @@ -172,69 +172,6 @@ static inline void showStackTrace() { #define INTS_TO_CHARS(input, length, output) #endif // defined(FLAG_DO_PROFILE) || defined(FLAG_DBG) -#ifdef FLAG_DO_PROFILE -// Profiler -#include - -#define PROF_BUF_SIZE 100 -static float profile_buf[PROF_BUF_SIZE]; -static float profile_old[PROF_BUF_SIZE]; -static unsigned int profile_counter[PROF_BUF_SIZE]; - -#define PROF_RESET prof_reset() -#define PROF_COUNT(prof_buf_id) ++profile_counter[prof_buf_id] -#define PROF_OPEN do { PROF_RESET; PROF_START(PROF_BUF_SIZE - 1); } while (0) -#define PROF_START(prof_buf_id) do { \ - PROF_COUNT(prof_buf_id); profile_old[prof_buf_id] = (clock()); } while (0) -#define PROF_CLOSE do { PROF_END(PROF_BUF_SIZE - 1); PROF_OUTALL; } while (0) -#define PROF_END(prof_buf_id) profile_buf[prof_buf_id] += ((clock()) - profile_old[prof_buf_id]) -#define PROF_CLOCKOUT(prof_buf_id) \ - AKLOGI("%s : clock is %f", __FUNCTION__, (clock() - profile_old[prof_buf_id])) -#define PROF_OUTALL do { AKLOGI("--- %s ---", __FUNCTION__); prof_out(); } while (0) - -static inline void prof_reset(void) { - for (int i = 0; i < PROF_BUF_SIZE; ++i) { - profile_buf[i] = 0; - profile_old[i] = 0; - profile_counter[i] = 0; - } -} - -static inline void prof_out(void) { - if (profile_counter[PROF_BUF_SIZE - 1] != 1) { - AKLOGI("Error: You must call PROF_OPEN before PROF_CLOSE."); - } - AKLOGI("Total time is %6.3f ms.", - profile_buf[PROF_BUF_SIZE - 1] * 1000.0f / static_cast(CLOCKS_PER_SEC)); - float all = 0.0f; - for (int i = 0; i < PROF_BUF_SIZE - 1; ++i) { - all += profile_buf[i]; - } - if (all < 1.0f) all = 1.0f; - for (int i = 0; i < PROF_BUF_SIZE - 1; ++i) { - if (profile_buf[i] > 0.0f) { - AKLOGI("(%d): Used %4.2f%%, %8.4f ms. Called %d times.", - i, (profile_buf[i] * 100.0f / all), - profile_buf[i] * 1000.0f / static_cast(CLOCKS_PER_SEC), - profile_counter[i]); - } - } -} - -#else // FLAG_DO_PROFILE -#define PROF_BUF_SIZE 0 -#define PROF_RESET -#define PROF_COUNT(prof_buf_id) -#define PROF_OPEN -#define PROF_START(prof_buf_id) -#define PROF_CLOSE -#define PROF_END(prof_buf_id) -#define PROF_CLOCK_OUT(prof_buf_id) -#define PROF_CLOCKOUT(prof_buf_id) -#define PROF_OUTALL - -#endif // FLAG_DO_PROFILE - #ifdef FLAG_DBG #define DEBUG_DICT true #define DEBUG_DICT_FULL false diff --git a/native/jni/src/suggest/core/suggest.cpp b/native/jni/src/suggest/core/suggest.cpp index c372d668b..e5e9b46bf 100644 --- a/native/jni/src/suggest/core/suggest.cpp +++ b/native/jni/src/suggest/core/suggest.cpp @@ -29,6 +29,7 @@ #include "suggest/core/result/suggestions_output_utils.h" #include "suggest/core/session/dic_traverse_session.h" #include "suggest/core/suggest_options.h" +#include "utils/profiler.h" namespace latinime { @@ -48,8 +49,8 @@ void Suggest::getSuggestions(ProximityInfo *pInfo, void *traverseSession, int *inputXs, int *inputYs, int *times, int *pointerIds, int *inputCodePoints, int inputSize, const float weightOfLangModelVsSpatialModel, SuggestionResults *const outSuggestionResults) const { - PROF_OPEN; - PROF_START(0); + PROF_INIT; + PROF_TIMER_START(0); const float maxSpatialDistance = TRAVERSAL->getMaxSpatialDistance(); DicTraverseSession *tSession = static_cast(traverseSession); tSession->setupForGetSuggestions(pInfo, inputCodePoints, inputSize, inputXs, inputYs, times, @@ -57,8 +58,8 @@ void Suggest::getSuggestions(ProximityInfo *pInfo, void *traverseSession, // TODO: Add the way to evaluate cache initializeSearch(tSession); - PROF_END(0); - PROF_START(1); + PROF_TIMER_END(0); + PROF_TIMER_START(1); // keep expanding search dicNodes until all have terminated. while (tSession->getDicTraverseCache()->activeSize() > 0) { @@ -66,12 +67,11 @@ void Suggest::getSuggestions(ProximityInfo *pInfo, void *traverseSession, tSession->getDicTraverseCache()->advanceActiveDicNodes(); tSession->getDicTraverseCache()->advanceInputIndex(inputSize); } - PROF_END(1); - PROF_START(2); + PROF_TIMER_END(1); + PROF_TIMER_START(2); SuggestionsOutputUtils::outputSuggestions( SCORING, tSession, weightOfLangModelVsSpatialModel, outSuggestionResults); - PROF_END(2); - PROF_CLOSE; + PROF_TIMER_END(2); } /** diff --git a/native/jni/src/utils/profiler.h b/native/jni/src/utils/profiler.h new file mode 100644 index 000000000..5f107fed3 --- /dev/null +++ b/native/jni/src/utils/profiler.h @@ -0,0 +1,86 @@ +/* + * Copyright (C) 2014, The Android Open Source Project + * + * Licensed 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 LATINIME_PROFILER_H +#define LATINIME_PROFILER_H + +#ifdef FLAG_DO_PROFILE + +#include "defines.h" + +#include +#include + +namespace latinime { + +class Profiler final { + public: + Profiler(const clockid_t clockId) + : mClockId(clockId), mStartTime(getTimeInMicroSec()), mStartTimes(), mTimes(), + mCounters() {} + + ~Profiler() { + const float totalTime = + static_cast(getTimeInMicroSec() - mStartTime) / 1000.f; + AKLOGI("Total time is %6.3f ms.", totalTime); + for (const auto &time : mTimes) { + AKLOGI("(%d): Used %4.2f%%, %8.4f ms. Called %d times.", time.first, + time.second / totalTime * 100.0f, time.second, mCounters[time.first]); + } + } + + void startTimer(const int id) { + mStartTimes[id] = getTimeInMicroSec(); + } + + void endTimer(const int id) { + mTimes[id] += static_cast(getTimeInMicroSec() - mStartTimes[id]) / 1000.0f; + mCounters[id]++; + } + + operator bool() const { return false; } + + private: + DISALLOW_IMPLICIT_CONSTRUCTORS(Profiler); + + const clockid_t mClockId; + int64_t mStartTime; + std::unordered_map mStartTimes; + std::unordered_map mTimes; + std::unordered_map mCounters; + + int64_t getTimeInMicroSec() { + timespec time; + clock_gettime(mClockId, &time); + return static_cast(time.tv_sec) * 1000000 + + static_cast(time.tv_nsec) / 1000; + } +}; +} // namespace latinime + +#define PROF_INIT Profiler __LATINIME__PROFILER__(CLOCK_THREAD_CPUTIME_ID) +#define PROF_TIMER_START(timer_id) __LATINIME__PROFILER__.startTimer(timer_id) +#define PROF_TIMER_END(timer_id) __LATINIME__PROFILER__.endTimer(timer_id) + +#else // FLAG_DO_PROFILE + +#define PROF_INIT +#define PROF_TIMER_START(timer_id) +#define PROF_TIMER_END(timer_id) + +#endif // FLAG_DO_PROFILE + +#endif /* LATINIME_PROFILER_H */