Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 7d5420aa authored by Keisuke Kuroyanagi's avatar Keisuke Kuroyanagi
Browse files

Make profiler use getTimeInMicroSec().

Bug: 17797064
Change-Id: Ie992c9454edfc3bf93d5ea367c3a4427b513a205
parent 61280c0b
Loading
Loading
Loading
Loading
+4 −4
Original line number Original line Diff line number Diff line
@@ -35,6 +35,7 @@
#include "utils/int_array_view.h"
#include "utils/int_array_view.h"
#include "utils/jni_data_utils.h"
#include "utils/jni_data_utils.h"
#include "utils/log_utils.h"
#include "utils/log_utils.h"
#include "utils/profiler.h"
#include "utils/time_keeper.h"
#include "utils/time_keeper.h"


namespace latinime {
namespace latinime {
@@ -43,8 +44,8 @@ class ProximityInfo;


static jlong latinime_BinaryDictionary_open(JNIEnv *env, jclass clazz, jstring sourceDir,
static jlong latinime_BinaryDictionary_open(JNIEnv *env, jclass clazz, jstring sourceDir,
        jlong dictOffset, jlong dictSize, jboolean isUpdatable) {
        jlong dictOffset, jlong dictSize, jboolean isUpdatable) {
    PROF_OPEN;
    PROF_INIT;
    PROF_START(66);
    PROF_TIMER_START(66);
    const jsize sourceDirUtf8Length = env->GetStringUTFLength(sourceDir);
    const jsize sourceDirUtf8Length = env->GetStringUTFLength(sourceDir);
    if (sourceDirUtf8Length <= 0) {
    if (sourceDirUtf8Length <= 0) {
        AKLOGE("DICT: Can't get sourceDir string");
        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 =
    Dictionary *const dictionary =
            new Dictionary(env, std::move(dictionaryStructureWithBufferPolicy));
            new Dictionary(env, std::move(dictionaryStructureWithBufferPolicy));
    PROF_END(66);
    PROF_TIMER_END(66);
    PROF_CLOSE;
    return reinterpret_cast<jlong>(dictionary);
    return reinterpret_cast<jlong>(dictionary);
}
}


+2 −65
Original line number Original line Diff line number Diff line
@@ -23,10 +23,10 @@
#define AK_FORCE_INLINE inline
#define AK_FORCE_INLINE inline
#endif // __GNUC__
#endif // __GNUC__


#if defined(FLAG_DO_PROFILE) || defined(FLAG_DBG)
#if defined(FLAG_DBG)
#undef AK_FORCE_INLINE
#undef AK_FORCE_INLINE
#define AK_FORCE_INLINE 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
// Must be equal to Constants.Dictionary.MAX_WORD_LENGTH in Java
#define MAX_WORD_LENGTH 48
#define MAX_WORD_LENGTH 48
@@ -172,69 +172,6 @@ static inline void showStackTrace() {
#define INTS_TO_CHARS(input, length, output)
#define INTS_TO_CHARS(input, length, output)
#endif // defined(FLAG_DO_PROFILE) || defined(FLAG_DBG)
#endif // defined(FLAG_DO_PROFILE) || defined(FLAG_DBG)


#ifdef FLAG_DO_PROFILE
// Profiler
#include <time.h>

#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<float>(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<float>(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
#ifdef FLAG_DBG
#define DEBUG_DICT true
#define DEBUG_DICT true
#define DEBUG_DICT_FULL false
#define DEBUG_DICT_FULL false
+8 −8
Original line number Original line Diff line number Diff line
@@ -29,6 +29,7 @@
#include "suggest/core/result/suggestions_output_utils.h"
#include "suggest/core/result/suggestions_output_utils.h"
#include "suggest/core/session/dic_traverse_session.h"
#include "suggest/core/session/dic_traverse_session.h"
#include "suggest/core/suggest_options.h"
#include "suggest/core/suggest_options.h"
#include "utils/profiler.h"


namespace latinime {
namespace latinime {


@@ -48,8 +49,8 @@ void Suggest::getSuggestions(ProximityInfo *pInfo, void *traverseSession,
        int *inputXs, int *inputYs, int *times, int *pointerIds, int *inputCodePoints,
        int *inputXs, int *inputYs, int *times, int *pointerIds, int *inputCodePoints,
        int inputSize, const float weightOfLangModelVsSpatialModel,
        int inputSize, const float weightOfLangModelVsSpatialModel,
        SuggestionResults *const outSuggestionResults) const {
        SuggestionResults *const outSuggestionResults) const {
    PROF_OPEN;
    PROF_INIT;
    PROF_START(0);
    PROF_TIMER_START(0);
    const float maxSpatialDistance = TRAVERSAL->getMaxSpatialDistance();
    const float maxSpatialDistance = TRAVERSAL->getMaxSpatialDistance();
    DicTraverseSession *tSession = static_cast<DicTraverseSession *>(traverseSession);
    DicTraverseSession *tSession = static_cast<DicTraverseSession *>(traverseSession);
    tSession->setupForGetSuggestions(pInfo, inputCodePoints, inputSize, inputXs, inputYs, times,
    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
    // TODO: Add the way to evaluate cache


    initializeSearch(tSession);
    initializeSearch(tSession);
    PROF_END(0);
    PROF_TIMER_END(0);
    PROF_START(1);
    PROF_TIMER_START(1);


    // keep expanding search dicNodes until all have terminated.
    // keep expanding search dicNodes until all have terminated.
    while (tSession->getDicTraverseCache()->activeSize() > 0) {
    while (tSession->getDicTraverseCache()->activeSize() > 0) {
@@ -66,12 +67,11 @@ void Suggest::getSuggestions(ProximityInfo *pInfo, void *traverseSession,
        tSession->getDicTraverseCache()->advanceActiveDicNodes();
        tSession->getDicTraverseCache()->advanceActiveDicNodes();
        tSession->getDicTraverseCache()->advanceInputIndex(inputSize);
        tSession->getDicTraverseCache()->advanceInputIndex(inputSize);
    }
    }
    PROF_END(1);
    PROF_TIMER_END(1);
    PROF_START(2);
    PROF_TIMER_START(2);
    SuggestionsOutputUtils::outputSuggestions(
    SuggestionsOutputUtils::outputSuggestions(
            SCORING, tSession, weightOfLangModelVsSpatialModel, outSuggestionResults);
            SCORING, tSession, weightOfLangModelVsSpatialModel, outSuggestionResults);
    PROF_END(2);
    PROF_TIMER_END(2);
    PROF_CLOSE;
}
}


/**
/**
+86 −0
Original line number Original line Diff line number Diff line
/*
 * 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 <ctime>
#include <unordered_map>

namespace latinime {

class Profiler final {
 public:
    Profiler(const clockid_t clockId)
            : mClockId(clockId), mStartTime(getTimeInMicroSec()), mStartTimes(), mTimes(),
              mCounters() {}

    ~Profiler() {
        const float totalTime =
                static_cast<float>(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<float>(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<int, int64_t> mStartTimes;
    std::unordered_map<int, float> mTimes;
    std::unordered_map<int, int> mCounters;

    int64_t getTimeInMicroSec() {
        timespec time;
        clock_gettime(mClockId, &time);
        return static_cast<int64_t>(time.tv_sec) * 1000000
                + static_cast<int64_t>(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 */