perf(server): time each segment of the per-keystroke candidate build
PrepareCandidateList runs on the shared task thread, so a stall inside it delays the hide/show messages queued behind it and reaches the screen as candidate-window flicker. The diagnostic log showed an identical workload take 8 ms once and 688 ms moments later, but not which segment paid for it. Split the function into measured segments and emit one "candidate build" line per keystroke, separating the engine candidate lookup from the user-dictionary fixed-position pass -- the latter opens a SQLite connection and runs its schema DDL on every call. Measurement only; no behaviour change.
This commit is contained in:
1 parent
bb53763e66
commit
0e003fa095
1 file changed
+49
@@ -3109,8 +3109,41 @@ void TsfDiagnosticPipeEventListenerLoopThread()
|
||||
}
|
||||
}
|
||||
|
||||
// Stopwatch for the per-keystroke candidate build. Everything this function does
|
||||
// runs on the shared task thread, so a stall anywhere in it delays the hide/show
|
||||
// messages queued behind it — which is what reaches the screen as flicker. The
|
||||
// splits exist to tell those segments apart: the engine candidate lookup and the
|
||||
// user-dictionary fixed-position pass both touch a database, and only a
|
||||
// measurement says which one is paying for it.
|
||||
class CandidateBuildTimer
|
||||
{
|
||||
public:
|
||||
// Milliseconds since the previous split, then restarts the segment.
|
||||
double Split()
|
||||
{
|
||||
const auto now = std::chrono::steady_clock::now();
|
||||
const double ms = std::chrono::duration<double, std::milli>(now - last_).count();
|
||||
last_ = now;
|
||||
return ms;
|
||||
}
|
||||
double TotalMs() const
|
||||
{
|
||||
return std::chrono::duration<double, std::milli>(std::chrono::steady_clock::now() - start_).count();
|
||||
}
|
||||
|
||||
private:
|
||||
std::chrono::steady_clock::time_point start_ = std::chrono::steady_clock::now();
|
||||
std::chrono::steady_clock::time_point last_ = start_;
|
||||
};
|
||||
|
||||
void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
{
|
||||
CandidateBuildTimer segment;
|
||||
// Zero means the branch taken this keystroke has no such segment, not that
|
||||
// the segment was instant.
|
||||
double queryMs = 0;
|
||||
double fixedPosMs = 0;
|
||||
|
||||
auto &ui = Global::candidate_ui;
|
||||
std::string pinyin = wstring_to_string(Global::PinyinString);
|
||||
const std::string current_input = g_inputSession->get_pinyin_sequence_with_cases();
|
||||
@@ -3153,8 +3186,10 @@ void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
const std::string typed = g_inputSession->get_pinyin_sequence();
|
||||
for (auto &item : items)
|
||||
item.pinyin = typed;
|
||||
queryMs = segment.Split();
|
||||
user_dictionary::apply_fixed_positions(user_dictionary::default_user_db_path(), CurrentRankingContextKey(),
|
||||
items, false);
|
||||
fixedPosMs = segment.Split();
|
||||
}
|
||||
else if (IsYModeInput(current_input))
|
||||
{
|
||||
@@ -3171,11 +3206,13 @@ void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
else
|
||||
{
|
||||
items = g_inputSession->get_candidates();
|
||||
queryMs = segment.Split();
|
||||
user_dictionary::apply_fixed_positions(
|
||||
user_dictionary::default_user_db_path(), CurrentRankingContextKey(), items,
|
||||
g_inputSession->get_pinyin_sequence().size() == 1,
|
||||
[](const std::string &key, const std::string &value) { return g_inputSession->find_candidate(key, value); },
|
||||
g_inputSession->has_active_helpcode());
|
||||
fixedPosMs = segment.Split();
|
||||
if (g_inputSession->get_pinyin_sequence().size() == 1 && items.size() > 24)
|
||||
items.resize(24);
|
||||
}
|
||||
@@ -3185,9 +3222,14 @@ void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
items.emplace_back(pinyin, pinyin, 1, CandidateSource::Fallback);
|
||||
}
|
||||
|
||||
// Whatever the branch above did that the two splits did not already claim.
|
||||
const double branchMs = segment.Split();
|
||||
const size_t itemCount = items.size();
|
||||
|
||||
ui.set_items(std::move(items));
|
||||
RefreshCandidatePageUi(false);
|
||||
PublishCandidateUiOwner(client_id, activation_epoch);
|
||||
const double uiMs = segment.Split();
|
||||
|
||||
const SchemeType scheme = g_inputSession->current_scheme_type();
|
||||
if (g_english_input_mode)
|
||||
@@ -3208,6 +3250,7 @@ void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
{
|
||||
UpdateEnglishInput("");
|
||||
}
|
||||
const double englishMs = segment.Split();
|
||||
|
||||
if (!g_english_input_mode && !IsSpecialModeCompositionActive(current_input) &&
|
||||
GetConfiguredEmojiMixedInputEnabled() && (scheme == SchemeType::Quanpin || scheme == SchemeType::Shuangpin) &&
|
||||
@@ -3219,6 +3262,7 @@ void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
{
|
||||
UpdateEmojiInput("");
|
||||
}
|
||||
const double emojiMs = segment.Split();
|
||||
|
||||
if (!g_english_input_mode && !IsSpecialModeCompositionActive(current_input) &&
|
||||
GetConfiguredKaomojiMixedInputEnabled() && (scheme == SchemeType::Quanpin || scheme == SchemeType::Shuangpin) &&
|
||||
@@ -3230,6 +3274,11 @@ void PrepareCandidateList(uint64_t client_id, uint64_t activation_epoch)
|
||||
{
|
||||
UpdateKaomojiInput("");
|
||||
}
|
||||
const double kaomojiMs = segment.Split();
|
||||
|
||||
CAND_DIAG_LOGF(L"candidate build total_ms={:.1f} query_ms={:.1f} fixed_pos_ms={:.1f} branch_ms={:.1f} "
|
||||
L"ui_ms={:.1f} english_ms={:.1f} emoji_ms={:.1f} kaomoji_ms={:.1f} items={}",
|
||||
segment.TotalMs(), queryMs, fixedPosMs, branchMs, uiMs, englishMs, emojiMs, kaomojiMs, itemCount);
|
||||
}
|
||||
|
||||
void ApplyCloudCandidate(const std::string &candidate, const std::string &pinyin, uint64_t generation,
|
||||
|
||||
Reference in new issue
Block a user