3
Help us understand the problem. What are the problem?

More than 1 year has passed since last update.

posted at

updated at

clocksource tsc が見つからない!?カーネルパッチを書いてみようとした話

KVM上で稼働する Linux で clocksourcetsc を認識できない問題があり、これを修正しようと試行錯誤した時のことをまとめてみました。基本的にディストリビューションにカスタムパッチを当ててみたものの、しっくりこず、その後本家のパッチを発見して勉強になった?という話です。
自分のブログにも同じ内容で投下していますが、Qiita にも記事を書いてみました。

経緯

これはもう1年以上前になろうかという時の話ですが、KVM上で稼働する Linux の clocksourceを調べていたら、tscが認識されないことがあるのに気がつきました。

tscは、x86系のハイパーバイザで稼働するLinuxのゲストにとっては、最も早くて正確な?カウンタデバイスであり、場合によってはこれが認識されないと困ってしまうかもしれません。
当時は、x86 Linux の 時間管理らへんのソースを読みまくっていたので、これならいけるかもとバグ探しを始めました。

具体的な症状

詳細:
clocksourcetscが登録されていない。以下のような感じです。

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
kvm-clock acpi_pm 

実例と類推

当時使用していたOS は、CentOS7 のカーネル kernel-3.10.0-957.el7 です。
まず、どのような問題がどこの部分にあるのか、Xenの場合と比較することも視野に、その症状から類推してみることにしました。

実例:CentOS7 on KVM

以下はdmesgの出力まで含めた確認の結果です。

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
kvm-clock acpi_pm 

$ dmesg | grep -iE '(clocksource|tsc)'
[    0.000000] tsc: Detected 3000.000 MHz processor
[    1.834422] TSC deadline timer enabled
[    2.600920] Switched to clocksource kvm-clock

CentOS 7のカーネルは Ubuntu などに比べて何も出力しなさすぎる気がしますが、、、
ただ上記のメッセージでも、デバイスとしてのTSC自体は認識されていることがわかって、結構なヒントになりそうな気がしました。

あとは正常な場合と比較しておくのも大事じゃないかということで確認してみました。
比較対象として適切かどうかはわかりませんが、幸いなことに今回は Xen で稼働する Linux ゲストでは問題が発生しないことがわかっていたので、そちらと比較しました。

Xenとの比較:CentOS7 on Xen

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
xen tsc hpet acpi_pm 

$ dmesg | grep -iE '(clocksource|tsc)'
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 2394.486 MHz processor
[    0.031000] tsc: Detected 2394.476 MHz TSC
[    0.607022] Switched to clocksource xen
[    2.244080] tsc: Refined TSC clocksource calibration: 2394.455 MHz

類推

TSC の周波数を検知するところまでにわずかに差はあるものの、違いは Refined TSC clocksource calibrationの有無にあることがわかります。
もちろんこの段階では、あくまで大雑把な推測の域を出ず、思い込みは厳禁です。

でも、ど素人の意見ですが、とにかく問題のある方(KVM で稼働するゲストの方)では、本当に何かエラーが出てるわけでもなくて、何も出力されていないというところが特に異常であるということが想像できます。 ここから、少なくとも、

  • clocksource 登録のロジック自体にも何か問題がありそうなことが予想できます。
  • 普通ダメな clocksource があるなら、それがダメなことを示すメッセージが出力されるはずなのです。

普段 Linux で遊んでいる経験上?こういう場合はある程度あたりをつけやすいので、(個人的には)デバッガを使うよりもソースコードを見たほうが早い気がしています。
あと、あまり褒められた方法ではないかもしれませんが、僕はprintkデバッグと組み合わせるのが大好きです。

原始的なデバッグ

printkであたりをつけて、ソースコードをじっと見てデバッグする。

僕にはカーネル開発者の知り合いがいたことはないし、本や雑誌やネットで得た知識しかないですが、printkデバッグもなかなかいい気がします。
いつ頃の話なのか不明ですが、netfilter開発者のラスティ・ラッセルさんはprintkとソースリストのにらめっこで問題を解決しているという記事を、古の雑誌で読んだことがあります[1]。

[1] 確かオープンソースマガジン。基本的に僕の知っている知識のほとんどが中古で購入した古の雑誌と書籍から吸収したものです。

実際、関数ポインタでぴょんぴょん飛んだり、何か複雑な処理のロジックで調査しなければいけないようなシチュエーションでない限りでは、だいたいソースコードを眺めてれば問題の箇所を見つけられる気がします。
また、そうではない場合はデバッガを使っても厳しい可能性があるような気がしています。

今回はprintkデバッグで解決できる典型だと思います。

ソースの準備

以下のコマンドでソースなどをインストールして準備しておきます。
これらの手順は CentOS の公式ページなどをみて実施した記憶があります。

$ sudo yumdownloader --source kernel-3.10.0-957.el7
$ sudo yum groupinstall "Development Tools" -y 
$ sudo yum install rpmdevtools -y
$ rpmdev-setuptree
$ rpm -Uvh kernel-3.10.0-957.el7.src.rpm
$ sudo yum-builddep -y --enablerepo=* rpmbuild/SPECS/kernel.spec
$ rpmbuild -bp ~/rpmbuild/SPECS/kernel.spec
$ cp -r ~/rpmbuild/BUILD/kernel-3.10.0-957.el7 ~/rpmbuild/BUILD/kernel-3.10.0-957.el7.orig
$ cp -al ~/rpmbuild/BUILD/kernel-3.10.0-957.el7.orig ~/rpmbuild/BUILD/kernel-3.10.0-957.el7.new

cp -al なのでvimで編集する場合には書き込み時にハードリンクを切る設定にします。
例えば下記の .vimrc

set nobackup
set writebackup
set backupcopy=no

マクロを組む

いちいちprintkの引数を考えるのは面倒なので、当たり前ですが、単純なマクロを組んでおきます。
例えば以下のもの:

#define __dprintk(n) \
printk("No.%s, func: %s, line: %d, file: %s\n", \
#n, __FUNCTION__, __LINE__, __FILE__);

何個目に挿入した printk なのかと、関数名、行番号、ファイル名を出力します。

バグのありそうな場所はどこですか?

それはもちろんclocksourceの登録がうまくいっていないので、clocksource tsc の登録を行う場所です。
printkをどのように打ったのかと共に、怪しそうな箇所を見ていきます。

入り口

基本的に TSC の処理に関するコードは /arch/x86/kernel/tsc.c に定義されていて、clocksourceclocksource_registar_hogehoge 関数で登録するのでその呼び出し箇所を確認します。

適当にgrepすると下記であるとわかります。

static int __init init_tsc_clocksource(void)
{
    if (!cpu_has_tsc || tsc_disabled > 0 || !tsc_khz)
        return 0;

    if (tsc_clocksource_reliable)
        clocksource_tsc.flags &= ~CLOCK_SOURCE_MUST_VERIFY;
    /* lower the rating if we already know its unstable: */
    if (check_tsc_unstable()) {
        clocksource_tsc.rating = 0;
        clocksource_tsc.flags &= ~CLOCK_SOURCE_IS_CONTINUOUS;
    }

    if (boot_cpu_has(X86_FEATURE_NONSTOP_TSC_S3))
        clocksource_tsc.flags |= CLOCK_SOURCE_SUSPEND_NONSTOP;

    /*
     * Trust the results of the earlier calibration on systems
     * exporting a reliable TSC.
     */
    if (boot_cpu_has(X86_FEATURE_TSC_RELIABLE)) {
        clocksource_register_khz(&clocksource_tsc, tsc_khz);
        return 0;
    }

    schedule_delayed_work(&tsc_irqwork, 0);
    return 0;
}
/*
 * We use device_initcall here, to ensure we run after the hpet
 * is fully initialized, which may occur at fs_initcall time.
 */
device_initcall(init_tsc_clocksource);

clocksource_register_khzがあるし。device_initcallもある。
これで間違いないと思う訳です。

TSCの周波数が信頼できるよとわかっていれば、X86_FEATURE_TSC_RELIABLE を立てて、clocksource_tsc をさっさと登録しちゃうことがわかります。ただし、TSC の周波数は起動時に都度計算するもので、普通は、そんなことはわからないので、このifブロックの中に入る訳ないよなぁと想像します。

ただ、これは本来おかしい気がします。pvclockの仕組み詳しい方なら、共有情報ページより周波数がハイパーバイザから割り当てらているを知っているので、X86_FEATURE_TSC_RELIABLEを立てちゃえば万事解決じゃない?と気がつけます。
発生の仕方から考えてこれは今回の問題の本質ではなさそうなので、一旦後回しにします。

すると関数の最後まで到達して、下記の処理が問題になっているのではと推測できます。

schedule_delayed_work(&tsc_irqwork, 0);

schedule_delayed_workは頻繁に使用する関数でご存知な方も多いと思います[2]。

普通にドキュメントに載っていますが、ドキュメントを見なくても、予想できます。なんかの処理へのポインタと遅延期間を渡して、非同期処理しているなとわかる訳です。

[2] schedule_delayed_work

目印の打ち方

なお、init_tsc_clocksource関数内部ではエラーを出力せずに早期リターンをしてそうな箇所があるので、念のため次の処理へ進んでいるか否かを確認するために、先ほど定義した__dprintkを打っておきます。
どこまで処理が進んでいるのか把握しているわけではないので、後々カーネルメッセージから追いかけやすいようにこのようにしました。

static int __init init_tsc_clocksource(void)
{
    if (!cpu_has_tsc || tsc_disabled > 0 || !tsc_khz)
        return 0;
__dprintk(1);
    if (tsc_clocksource_reliable)
        clocksource_tsc.flags &= ~CLOCK_SOURCE_MUST_VERIFY;
    /* lower the rating if we already know its unstable: */
    if (check_tsc_unstable()) {
        clocksource_tsc.rating = 0;
        clocksource_tsc.flags &= ~CLOCK_SOURCE_IS_CONTINUOUS;
    }

    if (boot_cpu_has(X86_FEATURE_NONSTOP_TSC_S3))
        clocksource_tsc.flags |= CLOCK_SOURCE_SUSPEND_NONSTOP;

    /*
     * Trust the results of the earlier calibration on systems
     * exporting a reliable TSC.
     */
    if (boot_cpu_has(X86_FEATURE_TSC_RELIABLE)) {
        clocksource_register_khz(&clocksource_tsc, tsc_khz);
        return 0;
    }
__dprintk(2);
    schedule_delayed_work(&tsc_irqwork, 0);
__dprintk(3);
    return 0;
}

以降も怪しそうな箇所をprintkを打ち込みながら見ていきます。見栄えは悪いです(苦笑い)。
また、printkは同期なので、これを打ちすぎるのもよろしくないので考えものです。。。あまりうちすぎるとスロットルされるか、逆にこれが問題になりそうです。

怪しそうな箇所

処理の続きはtsc_irqworkでした。
ソースリストの中からその正体を探すと下記だとわかります。

static DECLARE_DELAYED_WORK(tsc_irqwork, tsc_refine_calibration_work);
static void tsc_refine_calibration_work(struct work_struct *work)
{
    static u64 tsc_start = -1, ref_start;
    static int hpet;
    u64 tsc_stop, ref_stop, delta;
    unsigned long freq;

    /* Don't bother refining TSC on unstable systems */
    if (check_tsc_unstable())   // もしここでTSCが不正だと判定されていたら、
        goto out;       // outまで行った際に、エラーメッセージが出るはずなので
                            // ここは問題ではなさそうだが、念のため__dprintkを打っておく
__dprintk(4);

    /*
     * Since the work is started early in boot, we may be
     * delayed the first time we expire. So set the workqueue
     * again once we know timers are working.
     */
    // timerが正常に稼働していることが確認できるまで、
    // schedule_delayed_workで同じ処理を再帰的に呼び出そうとしているみたい。
    // 怪しそうなので内部に __dprintk を打っておく
    if (tsc_start == -1) {
__dprintk(5);
        /*
         * Only set hpet once, to avoid mixing hardware
         * if the hpet becomes enabled later.
         */
        hpet = is_hpet_enabled();
        schedule_delayed_work(&tsc_irqwork, HZ); // ここが怪しく見える。
        tsc_start = tsc_read_refs(&ref_start, hpet);
        return;
    }
__dprintk(6);

    // ここでも tsc_read_refs が出ていてこの関数が大事そうとわかる
    tsc_stop = tsc_read_refs(&ref_stop, hpet);

    // ref_startとref_stopには acpi_pmかhpetの値が入りそうとわかる。
    // ただこの場合も out まで行ったら何かメッセージが出そうなので関係なさそう。
    // 念のため printk
    // ACPI PM 自体は Nitro にもある。
    /* hpet or pmtimer available ? */
    if (ref_start == ref_stop)
        goto out;
__dprintk(7);

    // 以下をみると他もoutまで行けば何かしらのメッセージが出そうだと予測できる。
    // gotoの後ろに dprintk を挟みつつ先に進む

    /* Check, whether the sampling was disturbed by an SMI */
    if (tsc_start == ULLONG_MAX || tsc_stop == ULLONG_MAX)
        goto out;
__dprintk(8);

    delta = tsc_stop - tsc_start;
    delta *= 1000000LL;
    if (hpet)
        freq = calc_hpet_ref(delta, ref_start, ref_stop);
    else
        freq = calc_pmtimer_ref(delta, ref_start, ref_stop);

    /* Make sure we're within 1% */
    if (abs(tsc_khz - freq) > tsc_khz/100)
        goto out;
__dprintk(9);
    tsc_khz = freq;
    // ここまで到達できていないことは明らか
    pr_info("Refined TSC clocksource calibration: %lu.%03lu MHz\n",
        (unsigned long)tsc_khz / 1000,
        (unsigned long)tsc_khz % 1000);

out:
    if (boot_cpu_has(X86_FEATURE_ART))
        art_related_clocksource = &clocksource_tsc;
__dprintk(10);
    clocksource_register_khz(&clocksource_tsc, tsc_khz);
}

上記からも問題のありそうな位置がある程度予測できますが、printkがどうなるか確認してみましょう。

上記を確認用のパッチと仕立ててビルドしてみる

$ cd ~/rpmbuild/BUILD
$ diff -uNrp kernel-3.10.0-957.el7.orig kernel-3.10.0-957.el7.new > ../SOURCES/linux-3.10.0-957.el7.patch 
$ cd ../SOURCES
$ (rm linux-3.10.0-957.el7.patch && sed 's/kernel-[^ ][^ ]*[gw]\/lin/lin/g' > linux-3.10.0-957.el7.patch) < linux-3.10.0-957.el7.patch
$ cd ../BUILD
$ cd ~/rpmbuild/BUILD/kernel-3.10.0-957.el7/linux-3.10.0-957.el7.x86_64/
$ cp /boot/config-3.10.0-957.el7.x86_64 .config
$ make oldconfig
$ cp .config ~/rpmbuild/SOURCES/config-`uname -m`-generic
$ cd ~/rpmbuild/SPECS
$ vim kernel.spec
$ cat kernel.spec | grep -E '(tscheck|ApplyOptionalPatch.*[3].*|Patch1000)'
%define buildid .tscheck
Patch1000: linux-3.10.0-957.el7.patch
ApplyOptionalPatch linux-3.10.0-957.el7.patch 

$ rpmbuild -bb --with baseonly --without debuginfo --without debug --without doc --without perf --without tools --without kdump --without bootwrapper --target=`uname -m` kernel.spec
$ sudo yum localinstall -y ~/rpmbuild/RPMS/x86_64/kernel-*.rpm

printk の威力

下記のようになりました。
問題のありそうな箇所は一目瞭然でわかります。

$ dmesg | grep -iE '(clocksource|tsc)'
[    0.000000] Linux version 3.10.0-957.el7.tscheck.x86_64 ...
...
[    0.000000] tsc: Detected 3000.000 MHz processor
[    1.804286] TSC deadline timer enabled
[    2.557401] Switched to clocksource kvm-clock
[    3.035763] No.1, func: init_tsc_clocksource, line: 1309, file: arch/x86/kernel/tsc.c
[    3.044996] No.2, func: init_tsc_clocksource, line: 1330, file: arch/x86/kernel/tsc.c
[    3.054436] No.3, func: init_tsc_clocksource, line: 1332, file: arch/x86/kernel/tsc.c
[    3.063727] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[    3.073240] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
[    4.083424] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[    4.092902] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
[    5.085423] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[    5.085424] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
...
[   76.453766] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
[   77.464261] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[   77.473952] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
[   78.484266] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[   78.494070] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
...
[  627.100177] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
[  628.110663] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[  628.120099] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c

No.4とNo.5を延々とループしていることがわかります。
どうやら1秒おきの繰り返し処理で延々と続いていることがわかります。

ということで、予想通りに下記に問題がありそうであると断定できます。

if (tsc_start == -1) {
__dprintk(5);
    /*
     * Only set hpet once, to avoid mixing hardware
     * if the hpet becomes enabled later.
     */
    hpet = is_hpet_enabled();
    schedule_delayed_work(&tsc_irqwork, HZ); // ここが怪しく見える。
    tsc_start = tsc_read_refs(&ref_start, hpet);
    return;
}

処理内容からは、上記のブロックのtsc_startが常に -1となり、tsc_irqworkの再帰呼び出しが延々トループしてしまい。
結果、処理が進まずエラーも何も出力していない状況だったことがわかります。
この手の問題はむしろデバッガを使ってもわからない可能性の方が高いので今回printkを使ったのもそこまで悪くなさそうです。

では、tsc_start-1となるのはどんな時でしょうか?
それは、tsc_read_refsを読むとわかります。

問題の分析

tsc_read_refsは下記の定義

#define MAX_RETRIES     5
#define SMI_TRESHOLD    50000

/*
 * Read TSC and the reference counters. Take care of SMI disturbance
 */
static u64 tsc_read_refs(u64 *p, int hpet)
{
        u64 t1, t2;
        int i;

        for (i = 0; i < MAX_RETRIES; i++) {
                t1 = get_cycles();
                if (hpet)
                        *p = hpet_readl(HPET_COUNTER) & 0xFFFFFFFF;
                else
                        *p = acpi_pm_read_early();
                t2 = get_cycles();
                if ((t2 - t1) < SMI_TRESHOLD)
                        return t2;
        }
        return ULLONG_MAX;
}

なんと、どうやら-1だと思っていたのはULONG_MAXが返っていたらしいです。

具体的な処理は、以下のようになっているようです。

  1. まず t1 = get_cycles();で TSC のカウント値を読み取り
  2. 次に hpetacpi_pmのカウント値をIOアクセスして読み取る。
  3. その後、すぐt2 = get_cycles();でまた TSC のカウント値を読み取り
  4. IOアクセスの間に経過したカウント回数が SMI_TRESHOLD より小さければ t2を返す。
  5. そうでなければULLONG_MAXを返す。

つまりまとめると、このコードは下記の点で問題になっています。

原因の発見

TSCのカウントアップ速度が相対的に速すぎる(またはACPI_PMかHPETタイマーへの入出力が相対的に遅い)場合は、
t1 = get_cycles()t2 = get_cycles()の差が大きすぎ、t2 - t1は常にSMI_TRESHOLDより大きくなる。
その結果、tsc_startは常に-1になり、ブートプロセスが終了してもschedule_delayed_wor(&tsc_irqwork、HZ)で再試行を続ける。
最終的にに、TSCクロックソースの初期化が延々と遅れ、クロックソースtscが際限なく存在しない。
そして、この再試行プロセスはメッセージを表示しないために何がおきているのかわかりにくい。

パッチを書いてみる

デバッグのためにprintkを挿入するだけのパッチを書きましたが、実際に問題を修正するパッチも、もうかけます。
正しいか正しくないかは別にして、、、

ド素人の考えですが、この問題は2つの修正方法が考えられます。

  1. TSC の速さが早くなるのも、機器や環境によってはIOのレイテンシが上がるのも十分考えられるので、SMI_TRESHOLDが固定値なのは少しおかしい。
    何かいい方法がありそうな気がします。
  2. そもそも最初に触れましたが、pvclockではTSCの周波数はあらかじめわかっています。
    それを利用すれば煩わしい事とはおさらばなはずです。

上記の 1. と 2. の解決策で何かできないか具体的に考えていきます。

解決策1: SMI_TRESHOLDが固定値なのは少しおかしい。

SMI_TRESHOLDが固定値なのは少しおかしい気がします。
Linuxカーネルの深淵は僕にはわかりかねますが、素人目にみるとここは随分アバウトな処理で、システムに合わせてある程度スケールできるようになっておくべきだと思いました。
おそらく TSC の周波数に比例するような値にすべきだと思いますが。。。
でも正直どれだけとかは僕にはわかりませんでした。

(たった1日の祝日であり脳死状態で出した答え)

「もっと大きい固定値にしよう! 」

(大問題、ただし何が問題かはわからない)

50000 -> 5000000

下記のパッチを書いて見たよ。vol.1

diff -uNrp linux-3.10.0-957.el7.x86_64/arch/x86/kernel/tsc.c linux-3.10.0-957.el7.x86_64/arch/x86/kernel/tsc.c
--- linux-3.10.0-957.el7.x86_64/arch/x86/kernel/tsc.c    2019-07-28 18:54:36.422551294 +0000
+++ linux-3.10.0-957.el7.x86_64/arch/x86/kernel/tsc.c    2019-07-28 18:55:24.100351452 +0000
@@ -391,7 +391,7 @@ static int __init tsc_setup(char *str)
 __setup("tsc=", tsc_setup);

 #define MAX_RETRIES     5
-#define SMI_TRESHOLD    50000
+#define SMI_TRESHOLD    5000000

 /*
  * Read TSC and the reference counters. Take care of SMI disturbance

直ったよ。vol.1

$  cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
kvm-clock tsc acpi_pm 

$ dmesg | grep -iE '(clocksource|tsc)'
[    0.000000] tsc: Detected 3000.000 MHz processor
[    1.835560] TSC deadline timer enabled
[    2.605330] Switched to clocksource kvm-clock
[    3.086972] No.1, func: init_tsc_clocksource, line: 1309, file: arch/x86/kernel/tsc.c
[    3.096286] No.2, func: init_tsc_clocksource, line: 1330, file: arch/x86/kernel/tsc.c
[    3.105617] No.3, func: init_tsc_clocksource, line: 1332, file: arch/x86/kernel/tsc.c
[    3.114963] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[    3.124533] No.5, func: tsc_refine_calibration_work, line: 1256, file: arch/x86/kernel/tsc.c
[    4.209357] No.4, func: tsc_refine_calibration_work, line: 1248, file: arch/x86/kernel/tsc.c
[    4.219336] No.6, func: tsc_refine_calibration_work, line: 1266, file: arch/x86/kernel/tsc.c
[    4.229233] No.7, func: tsc_refine_calibration_work, line: 1273, file: arch/x86/kernel/tsc.c
[    4.239024] No.8, func: tsc_refine_calibration_work, line: 1278, file: arch/x86/kernel/tsc.c
[    4.248844] No.9, func: tsc_refine_calibration_work, line: 1290, file: arch/x86/kernel/tsc.c
[    4.258687] tsc: Refined TSC clocksource calibration: 3000.004 MHz
[    4.264562] No.10, func: tsc_refine_calibration_work, line: 1300, file: arch/x86/kernel/tsc.c

解決策2: 仮想化ゲストなのに、pvclockのTSC周波数を用いないのは少しおかしい

最初の方にも言いましたが、pvclockの仕組み詳しい方なら、共有情報ページより周波数が基盤から割り当てられていることを知っているので、TSCを認識した(kvm-clockを認識した)時点でTSCの周波数は基盤から計算済みのものが与えられているとわかっています。
なので、kvm-clockを認識した時点で、X86_FEATURE_TSC_RELIABLEを立てちゃえば万事解決じゃない?と気がつけます。pvlockはそもそも TSC を仮想環境ように拡張したプロトコルです。

下記の部分ですね。

/*
 * Trust the results of the earlier calibration on systems
 * exporting a reliable TSC.
 */
if (boot_cpu_has(X86_FEATURE_TSC_RELIABLE)) {
    clocksource_register_khz(&clocksource_tsc, tsc_khz);
    return 0;
}

kvm-clock を認識した際にTSCの周波数を検知する処理があるはずなので、
上記の部分で if の中に入れるように、kvm-clockのコードを修正して見ます。

対象のkvm-clockのソースは下記です。
KVMで稼働したゲストの初期化処理の中でkvm_get_tsc_khzが呼ばれることがわかります。
ソースコードのコメントからもここで TSC の周波数を早めに求めてしまうことがなんとなくわかります。

static unsigned long kvm_get_tsc_khz(void)
{
        struct pvclock_vcpu_time_info *src;
        int cpu;
        unsigned long tsc_khz;
   ...
        src = &hv_clock[cpu].pvti;
        tsc_khz = pvclock_tsc_khz(src);
        preempt_enable();
        return tsc_khz;
}
...
void __init kvmclock_init(void)
{
    ...
        x86_platform.calibrate_tsc = kvm_get_tsc_khz;
        x86_platform.calibrate_cpu = kvm_get_tsc_khz;
...

なお、cpuのフラグは arch/x86/kernel/cpu/mkcapflags.plarch/x86/include/asm/cpufeature.h のマクロで管理しているのは Linux User ならご存知かと思います。
フラグを強制的に立てるものはないか探してみるとarch/x86/include/asm/cpufeature.h下記がありました。

#define set_cpu_cap(c, bit)    set_bit(bit, (unsigned long *)((c)->x86_capability))

extern void setup_clear_cpu_cap(unsigned int bit);
extern void clear_cpu_cap(struct cpuinfo_x86 *c, unsigned int bit);

#define setup_force_cpu_cap(bit) do { \
    set_cpu_cap(&boot_cpu_data, bit);    \
    set_bit(bit, (unsigned long *)cpu_caps_set);    \
} while (0)

これを使います。

下記のパッチを書いて見たよ。vol.2

diff -uNrp linux-3.10.0-957.el7.x86_64/arch/x86/kernel/kvmclock.c linux-3.10.0-957.el7.x86_64/arch/x86/kernel/kvmclock.c
--- linux-3.10.0-957.el7.x86_64/arch/x86/kernel/kvmclock.c    2019-07-29 02:35:27.318987845 +0000
+++ linux-3.10.0-957.el7.x86_64/arch/x86/kernel/kvmclock.c    2019-07-29 03:04:11.015862936 +0000
@@ -338,6 +338,7 @@ void __init kvmclock_init(void)

     x86_platform.calibrate_tsc = kvm_get_tsc_khz;
     x86_platform.calibrate_cpu = kvm_get_tsc_khz;
+    setup_force_cpu_cap(X86_FEATURE_TSC_RELIABLE);
     x86_platform.get_wallclock = kvm_get_wallclock;
     x86_platform.set_wallclock = kvm_set_wallclock;
 #ifdef CONFIG_X86_LOCAL_APIC

直ったよ。vol.2

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource 
kvm-clock tsc acpi_pm 

$  dmesg | grep -iE '(clocksource|tsc)'
[    0.000000] Linux version 3.10.0-957.21.3.el7.tsc_fixed.x86_64...
...
[    0.000000] tsc: Detected 3000.000 MHz processor
[    1.832686] TSC deadline timer enabled
[    1.929653] Skipped synchronization checks as TSC is reliable.
[    2.598602] Switched to clocksource kvm-clock
[    3.078334] No.1, func: init_tsc_clocksource, line: 1309, file: arch/x86/kernel/tsc.c

パッチが書かれていないはずがない!

CentOS/RHEL で使われてるカーネルってちょっと古めです。なので、正直に言ってディストリビューションで見つかるバグっていうのは、たいていの場合、upstreamではもうすでに修正済みなことがほとんどだと思います。
ということで探してみたら、あっさりと見つかってしまいましたorz。

解決策1 よりも優れたパッチ

予想通り、TSCの周波数に比例してスケールするような修正が施されていました。
ULONG_MAX の比較方法も修正されています。

何かの値と比例させていときにはシフトしておけばいいと理解しました(違う。
細かい部分はよくわからないけどCSの真髄みたいなパッチだなと思いました。
ほーこういう感じかととても勉強になったので次回に生かしたいです。

x86/tsc: Make calibration refinement more robust

特徴的なところだけ抜粋

diff --git a/arch/x86/kernel/tsc.c b/arch/x86/kernel/tsc.c
index e9f777b..3fae238 100644
--- a/arch/x86/kernel/tsc.c
+++ b/arch/x86/kernel/tsc.c
@@ -297,15 +297,16 @@ static int __init tsc_setup(char *str)

 __setup("tsc=", tsc_setup);

-#define MAX_RETRIES     5
-#define SMI_TRESHOLD    50000
+#define MAX_RETRIES        5
+#define TSC_DEFAULT_THRESHOLD  0x20000

 /*
- * Read TSC and the reference counters. Take care of SMI disturbance
+ * Read TSC and the reference counters. Take care of any disturbances
  */
 static u64 tsc_read_refs(u64 *p, int hpet)
 {
    u64 t1, t2;
+   u64 thresh = tsc_khz ? tsc_khz >> 5 : TSC_DEFAULT_THRESHOLD;
    int i;

    for (i = 0; i < MAX_RETRIES; i++) {
@@ -315,7 +316,7 @@ static u64 tsc_read_refs(u64 *p, int hpet)
        else
            *p = acpi_pm_read_early();
        t2 = get_cycles();
-       if ((t2 - t1) < SMI_TRESHOLD)
+       if ((t2 - t1) < thresh)
            return t2;
    }
    return ULLONG_MAX;

解決策2 と類似のパッチ

RHELのコードは少し古いので、セットする CPU フラグに少し差がありますが、
正直、setup_force_cpu_capをこのブロックに挿入した意味は僕には良くわかりませんでした。このコードだと何回も CPU フラグをセットし直すことになります。何の意味があるんだろうと思っていますが、何か意味があるのかもしれません。

kvmclock: fix TSC calibration for nested guests

diff --git a/arch/x86/kernel/kvmclock.c b/arch/x86/kernel/kvmclock.c
index d79a18b..4c53d12 100644
--- a/arch/x86/kernel/kvmclock.c
+++ b/arch/x86/kernel/kvmclock.c
@@ -138,6 +138,7 @@ static unsigned long kvm_get_tsc_khz(void)
    src = &hv_clock[cpu].pvti;
    tsc_khz = pvclock_tsc_khz(src);
    put_cpu();
+   setup_force_cpu_cap(X86_FEATURE_TSC_KNOWN_FREQ);
    return tsc_khz;
 }

あとがき

Linux 難しいけど楽しいですね。
ちなみにボクは Rust が大好きで Linux 用にブートローダーを書いたりもしてます。こちらも紹介記事にしてあるので、よかったら読んでみてください。

Rust で vmlinux を起動できる x86 ブートローダーを作ってみた話 - Qiita

ここはこうした方がいいんじゃないなどのアドバイスなどもあったらお気軽にコメントください。勉強します!

Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Sign upLogin
3
Help us understand the problem. What are the problem?