From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S1755027AbdJITdx (ORCPT <rfc822;w@1wt.eu>);
        Mon, 9 Oct 2017 15:33:53 -0400
Received: from mailgw1.fjfi.cvut.cz ([147.32.9.3]:60692 "EHLO
        mailgw1.fjfi.cvut.cz" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
        with ESMTP id S1754197AbdJITdw (ORCPT
        <rfc822;linux-kernel@vger.kernel.org>);
        Mon, 9 Oct 2017 15:33:52 -0400
X-CTU-FNSPE-Virus-Scanned: amavisd-new at fjfi.cvut.cz
DKIM-Filter: OpenDKIM Filter v2.11.0 mailgw1.fjfi.cvut.cz C14B4A0476
Date: Mon, 9 Oct 2017 21:33:37 +0200 (CEST)
From: David Kozub <zub@linux.fjfi.cvut.cz>
To: Daniel Lezcano <daniel.lezcano@linaro.org>
cc: Thomas Gleixner <tglx@linutronix.de>, linux-kernel@vger.kernel.org
Subject: Re: PROBLEM: Kernel BUG in mfgpt_tick (cs5535-clockevt.c) on ALIX
 2c3 - null call
In-Reply-To: <8de07c60-8d37-802a-837c-a6cf356d1535@linaro.org>
Message-ID: <alpine.LRH.2.21.1710092047250.22810@linux.fjfi.cvut.cz>
References: <alpine.LRH.2.21.1710072316020.4511@linux.fjfi.cvut.cz> <8de07c60-8d37-802a-837c-a6cf356d1535@linaro.org>
User-Agent: Alpine 2.21 (LRH 202 2017-01-01)
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="546533125-1366019645-1507577618=:22810"
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

  This message is in MIME format.  The first part should be readable text,
  while the remaining parts are likely unreadable without MIME-aware tools.

--546533125-1366019645-1507577618=:22810
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8BIT

On Mon, 9 Oct 2017, Daniel Lezcano wrote:

> On 07/10/2017 23:26, David Kozub wrote:
>> Hi all,
>>
>> booting up kernel 4.14-rc3 with CS5535_CLOCK_EVENT_SRC on an ALIX 2c3
>> (http://pcengines.ch/alix2c3.htm) dies with:
>>
>> [    2.313086] cs5535-smb cs5535-smb: SCx200 device 'CS5535 ACB0'
>> registered
>> [    2.338711] cs5535-mfgpt cs5535-mfgpt: registered timer 0
>> [    2.355676] ledtrig-cpu: registered to indicate activity on CPUs
>> [    2.373745] cs5535-mfgpt cs5535-mfgpt: registered timer 1
>> [    2.389976] cs5535-clockevt: Registering MFGPT timer as a clock
>> event, using IRQ 7
>> [    2.412687] BUG: unable to handle kernel NULL pointer dereference
>> at   (null)
>> [    2.412698] IP:   (null)
>> [    2.412702] *pde = 00000000
>> [    2.412713] Oops: 0000 [#1]
>> [    2.412716] Modules linked in:
>> [    2.412732] CPU: 0 PID: 1 Comm: swapper Not tainted
>> 4.14.0-rc3-humel-test17 #36
>> [    2.412739] task: c0010000 task.stack: c008e000
>> [    2.412744] EIP:   (null)
>> [    2.412749] EFLAGS: 00210093 CPU: 0
>> [    2.412758] EAX: c05fb8c0 EBX: c05fb880 ECX: 00000000 EDX: 0000620c
>> [    2.412769] ESI: c0009fd4 EDI: c014e14e EBP: c0009fac ESP: c0009fa8
>> [    2.412780]  DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068
>> [    2.412790] CR0: 80050033 CR2: 00000000 CR3: 0064f000 CR4: 00000090
>> [    2.412793] Call Trace:
>> [    2.412800]  <IRQ>
>> [    2.412825]  ? mfgpt_tick+0x5d/0x81
>> [    2.412845]  __handle_irq_event_percpu+0x56/0xb6
>> [    2.412864]  ? handle_fasteoi_irq+0xf3/0xf3
>> [    2.412878]  handle_irq_event_percpu+0x17/0x3f
>> [    2.412892]  handle_irq_event+0x1d/0x29
>> [    2.412905]  handle_level_irq+0x57/0xc6
>> [    2.412924]  handle_irq+0x47/0x52
>> [    2.412929]  </IRQ>
>> [    2.412934]  <SOFTIRQ>
>> [    2.412949]  do_IRQ+0x32/0x9b
>> [    2.412963]  ? __irqentry_text_end+0x7/0x7
>> [    2.412976]  common_interrupt+0x2e/0x34
>> ...
>>
>> The problem seems to be in drivers/clocksource/cs5535-clockevt.c in
>> mfgpt_tick() on line 132:
>> ...
>>     cs5535_clockevent.event_handler(&cs5535_clockevent);
>> ...
>> cs5535_clockevent.event_handler is null.
>>
>> Adding some more traces I see mfgpt_tick() gets called before
>> clockevents_config_and_register() finishes (invoked from
>> cs5535_mfgpt_init() on line 178). So when mfgpt_tick() accessess the
>> event_handler, it's NULL. Wrapping the event_handler call on line 132 in
>> a null pointer check results in a working system.
>>
>> The issue is present at least also in kernel 4.13.5. In kernel versions
>> <= 4.1-rc6 the cs5535_clockevent worked OK. Kernels >= 4.1-rc7 never
>> booted at all on my ALIX 2c3 (last I tried 4.5, then gave up and tried
>> 4.13.5 recently), so I don't know when exactly this issue appeared.
>>
>> My guess is that the timer interrupt is enabled too early. If I change
>> the order of clockevents_config_and_register() and
>> cs5535_mfgpt_write(cs5535_event_clock, MFGPT_REG_SETUP, val) in
>> cs5535_mfgpt_init() like this:
>> ...
>>     /* Set up the clock event */
>>     printk(KERN_INFO DRV_NAME
>>         ": Registering MFGPT timer as a clock event, using IRQ %d\n",
>>         timer_irq);
>>     clockevents_config_and_register(&cs5535_clockevent, MFGPT_HZ,
>>                     0xF, 0xFFFE);
>>
>>     /* Set the clock scale and enable the event mode for CMP2 */
>>     val = MFGPT_SCALE | (3 << 8);
>>     cs5535_mfgpt_write(cs5535_event_clock, MFGPT_REG_SETUP, val);
>> ...
>> the system boots and seems to be OK.
>
> What happens if instead of inverting those two lines, you add
> mfgpt_shutdown() early in the init function ?

Hi Daniel,

I can't call mfgpt_shutdown() before clockevents_config_and_register() as 
mfgpt_shutdown() wants a struct clock_event_device* which is only 
available after clockevents_config_and_register(). But I tried calling 
disable_timer():

@@ -152,6 +152,8 @@ static int __init cs5535_mfgpt_init(void)
         }
         cs5535_event_clock = timer;

+       disable_timer(cs5535_event_clock);
+
         /* Set up the IRQ on the MFGPT side */
         if (cs5535_mfgpt_setup_irq(timer, MFGPT_CMP2, &timer_irq)) {
                 printk(KERN_ERR DRV_NAME ": Could not set up IRQ %d\n",

which should do the same thing. Unfortunately I still get the same BUG.

I added some more traces and I think the IRQ comes just after:
 	ret = setup_irq(timer_irq, &mfgptirq);

(And my reordering of cs5535_mfgpt_write and 
clockevents_config_and_register was just lucky, because the confing and 
register occured sooner than the IRQ.)

Attached is a patch that shows where I added the traces. It produces the 
following output (I also added a bunch of sleeps in between to be sure 
which step triggers the mfgpt_tick call):

[    3.229612] cs5535-clockevt: enabling verbose handler
[    3.234699] cs5535-clockevt: sleeping(1)...
[    4.320051] cs5535-clockevt: done(1)
[    4.323641] cs5535-clockevt: calling cs5535_mfgpt_alloc_timer
[    4.329402] cs5535-mfgpt cs5535-mfgpt: registered timer 1
[    4.334835] cs5535-clockevt: sleeping(2)...
[    5.360051] cs5535-clockevt: done(2)
[    5.363632] cs5535-clockevt: calling disable_timer
[    5.368425] cs5535-clockevt: sleeping(3)...
[    6.400048] cs5535-clockevt: done(3)
[    6.403631] cs5535-clockevt: calling cs5535_mfgpt_setup_irq
[    6.409214] cs5535-clockevt: sleeping(4)...
[    7.440044] cs5535-clockevt: done(4)
[    7.443623] cs5535-clockevt: calling setup_irq
[    7.448088] cs5535-clockevt: mfgpt_tick called
[    7.452579] cs5535-clockevt: sleeping(5)...
[    8.480049] cs5535-clockevt: done(5)
[    8.483634] cs5535-clockevt: doing write
[    8.487559] cs5535-clockevt: sleeping(6)...
[    9.520051] cs5535-clockevt: done(6)
[    9.523635] cs5535-clockevt: Registering MFGPT timer as a clock event, 
using IRQ 7
[    9.531263] cs5535-clockevt: clockevents_config_and_register returned
[    9.537706] cs5535-clockevt: disabling verbose handler

(I observed the boot 3 times and the sequence is always the same.)

Best regards,
David
--546533125-1366019645-1507577618=:22810
Content-Type: text/plain; charset=US-ASCII; name=cs5535-traces-hack.patch
Content-Transfer-Encoding: BASE64
Content-ID: <alpine.LRH.2.21.1710092133370.22810@linux.fjfi.cvut.cz>
Content-Description: 
Content-Disposition: attachment; filename=cs5535-traces-hack.patch

ZGlmZiAtLWdpdCBhL2RyaXZlcnMvY2xvY2tzb3VyY2UvY3M1NTM1LWNsb2Nr
ZXZ0LmMgYi9kcml2ZXJzL2Nsb2Nrc291cmNlL2NzNTUzNS1jbG9ja2V2dC5j
DQppbmRleCBhMWRmNTg4MzQzZjIuLjQ0NmJiNTk1MDMwYiAxMDA2NDQNCi0t
LSBhL2RyaXZlcnMvY2xvY2tzb3VyY2UvY3M1NTM1LWNsb2NrZXZ0LmMNCisr
KyBiL2RyaXZlcnMvY2xvY2tzb3VyY2UvY3M1NTM1LWNsb2NrZXZ0LmMNCkBA
IC0xOCw5ICsxOCwxMiBAQA0KICNpbmNsdWRlIDxsaW51eC9tb2R1bGUuaD4N
CiAjaW5jbHVkZSA8bGludXgvY3M1NTM1Lmg+DQogI2luY2x1ZGUgPGxpbnV4
L2Nsb2NrY2hpcHMuaD4NCisjaW5jbHVkZSA8bGludXgvZGVsYXkuaD4NCiAN
CiAjZGVmaW5lIERSVl9OQU1FICJjczU1MzUtY2xvY2tldnQiDQogDQorc3Rh
dGljIGludCB2ZXJib3NlX2hhbmRsZXIgPSAwOw0KKw0KIHN0YXRpYyBpbnQg
dGltZXJfaXJxOw0KIG1vZHVsZV9wYXJhbV9od19uYW1lZChpcnEsIHRpbWVy
X2lycSwgaW50LCBpcnEsIDA2NDQpOw0KIE1PRFVMRV9QQVJNX0RFU0MoaXJx
LCAiV2hpY2ggSVJRIHRvIHVzZSBmb3IgdGhlIGNsb2NrIHNvdXJjZSBNRkdQ
VCB0aWNrcy4iKTsNCkBAIC0xMjksNyArMTMyLDE0IEBAIHN0YXRpYyBpcnFy
ZXR1cm5fdCBtZmdwdF90aWNrKGludCBpcnEsIHZvaWQgKmRldl9pZCkNCiAJ
CWNzNTUzNV9tZmdwdF93cml0ZShjczU1MzVfZXZlbnRfY2xvY2ssIE1GR1BU
X1JFR19TRVRVUCwNCiAJCQkJTUZHUFRfU0VUVVBfQ05URU4gfCBNRkdQVF9T
RVRVUF9DTVAyKTsNCiANCi0JY3M1NTM1X2Nsb2NrZXZlbnQuZXZlbnRfaGFu
ZGxlcigmY3M1NTM1X2Nsb2NrZXZlbnQpOw0KKwlpZiAodmVyYm9zZV9oYW5k
bGVyKQ0KKwkJcHJpbnRrKEtFUk5fSU5GTyBEUlZfTkFNRSAiOiBtZmdwdF90
aWNrIGNhbGxlZFxuIik7DQorDQorCWlmICghdmVyYm9zZV9oYW5kbGVyICYm
IGNzNTUzNV9jbG9ja2V2ZW50LmV2ZW50X2hhbmRsZXIgPT0gTlVMTCkNCisJ
CXByaW50ayhLRVJOX0VSUiBEUlZfTkFNRSAiOiBtZmdwdF90aWNrIHdpdGgg
bnVsbCBldmVudF9oYW5kbGVyIHdoaWxlIG5vdCB2ZXJib3NlIVxuIik7DQor
DQorCWlmIChjczU1MzVfY2xvY2tldmVudC5ldmVudF9oYW5kbGVyICE9IE5V
TEwpDQorCQljczU1MzVfY2xvY2tldmVudC5ldmVudF9oYW5kbGVyKCZjczU1
MzVfY2xvY2tldmVudCk7DQogCXJldHVybiBJUlFfSEFORExFRDsNCiB9DQog
DQpAQCAtMTQ1LDYgKzE1NSwxNCBAQCBzdGF0aWMgaW50IF9faW5pdCBjczU1
MzVfbWZncHRfaW5pdCh2b2lkKQ0KIAlpbnQgcmV0Ow0KIAl1aW50MTZfdCB2
YWw7DQogDQorCXByaW50ayhLRVJOX0lORk8gRFJWX05BTUUgIjogZW5hYmxp
bmcgdmVyYm9zZSBoYW5kbGVyXG4iKTsNCisJV1JJVEVfT05DRSh2ZXJib3Nl
X2hhbmRsZXIsIDEpOw0KKw0KKwlwcmludGsoS0VSTl9JTkZPIERSVl9OQU1F
ICI6IHNsZWVwaW5nKDEpLi4uXG4iKTsNCisJbXNsZWVwKDEwMDApOw0KKwlw
cmludGsoS0VSTl9JTkZPIERSVl9OQU1FICI6IGRvbmUoMSlcbiIpOw0KKw0K
KwlwcmludGsoS0VSTl9JTkZPIERSVl9OQU1FICI6IGNhbGxpbmcgY3M1NTM1
X21mZ3B0X2FsbG9jX3RpbWVyXG4iKTsNCiAJdGltZXIgPSBjczU1MzVfbWZn
cHRfYWxsb2NfdGltZXIoTUZHUFRfVElNRVJfQU5ZLCBNRkdQVF9ET01BSU5f
V09SS0lORyk7DQogCWlmICghdGltZXIpIHsNCiAJCXByaW50ayhLRVJOX0VS
UiBEUlZfTkFNRSAiOiBDb3VsZCBub3QgYWxsb2NhdGUgTUZHUFQgdGltZXJc
biIpOw0KQEAgLTE1Miw2ICsxNzAsMTggQEAgc3RhdGljIGludCBfX2luaXQg
Y3M1NTM1X21mZ3B0X2luaXQodm9pZCkNCiAJfQ0KIAljczU1MzVfZXZlbnRf
Y2xvY2sgPSB0aW1lcjsNCiANCisJcHJpbnRrKEtFUk5fSU5GTyBEUlZfTkFN
RSAiOiBzbGVlcGluZygyKS4uLlxuIik7DQorCW1zbGVlcCgxMDAwKTsNCisJ
cHJpbnRrKEtFUk5fSU5GTyBEUlZfTkFNRSAiOiBkb25lKDIpXG4iKTsNCisN
CisJcHJpbnRrKEtFUk5fSU5GTyBEUlZfTkFNRSAiOiBjYWxsaW5nIGRpc2Fi
bGVfdGltZXJcbiIpOw0KKwlkaXNhYmxlX3RpbWVyKGNzNTUzNV9ldmVudF9j
bG9jayk7DQorDQorCXByaW50ayhLRVJOX0lORk8gRFJWX05BTUUgIjogc2xl
ZXBpbmcoMykuLi5cbiIpOw0KKwltc2xlZXAoMTAwMCk7DQorCXByaW50ayhL
RVJOX0lORk8gRFJWX05BTUUgIjogZG9uZSgzKVxuIik7DQorDQorCXByaW50
ayhLRVJOX0lORk8gRFJWX05BTUUgIjogY2FsbGluZyBjczU1MzVfbWZncHRf
c2V0dXBfaXJxXG4iKTsNCiAJLyogU2V0IHVwIHRoZSBJUlEgb24gdGhlIE1G
R1BUIHNpZGUgKi8NCiAJaWYgKGNzNTUzNV9tZmdwdF9zZXR1cF9pcnEodGlt
ZXIsIE1GR1BUX0NNUDIsICZ0aW1lcl9pcnEpKSB7DQogCQlwcmludGsoS0VS
Tl9FUlIgRFJWX05BTUUgIjogQ291bGQgbm90IHNldCB1cCBJUlEgJWRcbiIs
DQpAQCAtMTU5LDYgKzE4OSwxMSBAQCBzdGF0aWMgaW50IF9faW5pdCBjczU1
MzVfbWZncHRfaW5pdCh2b2lkKQ0KIAkJZ290byBlcnJfdGltZXI7DQogCX0N
CiANCisJcHJpbnRrKEtFUk5fSU5GTyBEUlZfTkFNRSAiOiBzbGVlcGluZyg0
KS4uLlxuIik7DQorCW1zbGVlcCgxMDAwKTsNCisJcHJpbnRrKEtFUk5fSU5G
TyBEUlZfTkFNRSAiOiBkb25lKDQpXG4iKTsNCisNCisJcHJpbnRrKEtFUk5f
SU5GTyBEUlZfTkFNRSAiOiBjYWxsaW5nIHNldHVwX2lycVxuIik7DQogCS8q
IEFuZCByZWdpc3RlciBpdCB3aXRoIHRoZSBrZXJuZWwgKi8NCiAJcmV0ID0g
c2V0dXBfaXJxKHRpbWVyX2lycSwgJm1mZ3B0aXJxKTsNCiAJaWYgKHJldCkg
ew0KQEAgLTE2NiwxNyArMjAxLDMwIEBAIHN0YXRpYyBpbnQgX19pbml0IGNz
NTUzNV9tZmdwdF9pbml0KHZvaWQpDQogCQlnb3RvIGVycl9pcnE7DQogCX0N
CiANCisJcHJpbnRrKEtFUk5fSU5GTyBEUlZfTkFNRSAiOiBzbGVlcGluZyg1
KS4uLlxuIik7DQorCW1zbGVlcCgxMDAwKTsNCisJcHJpbnRrKEtFUk5fSU5G
TyBEUlZfTkFNRSAiOiBkb25lKDUpXG4iKTsNCisNCiAJLyogU2V0IHRoZSBj
bG9jayBzY2FsZSBhbmQgZW5hYmxlIHRoZSBldmVudCBtb2RlIGZvciBDTVAy
ICovDQogCXZhbCA9IE1GR1BUX1NDQUxFIHwgKDMgPDwgOCk7DQogDQorCXBy
aW50ayhLRVJOX0lORk8gRFJWX05BTUUgIjogZG9pbmcgd3JpdGVcbiIpOw0K
IAljczU1MzVfbWZncHRfd3JpdGUoY3M1NTM1X2V2ZW50X2Nsb2NrLCBNRkdQ
VF9SRUdfU0VUVVAsIHZhbCk7DQogDQorCXByaW50ayhLRVJOX0lORk8gRFJW
X05BTUUgIjogc2xlZXBpbmcoNikuLi5cbiIpOw0KKwltc2xlZXAoMTAwMCk7
DQorCXByaW50ayhLRVJOX0lORk8gRFJWX05BTUUgIjogZG9uZSg2KVxuIik7
DQorDQogCS8qIFNldCB1cCB0aGUgY2xvY2sgZXZlbnQgKi8NCiAJcHJpbnRr
KEtFUk5fSU5GTyBEUlZfTkFNRQ0KIAkJIjogUmVnaXN0ZXJpbmcgTUZHUFQg
dGltZXIgYXMgYSBjbG9jayBldmVudCwgdXNpbmcgSVJRICVkXG4iLA0KIAkJ
dGltZXJfaXJxKTsNCiAJY2xvY2tldmVudHNfY29uZmlnX2FuZF9yZWdpc3Rl
cigmY3M1NTM1X2Nsb2NrZXZlbnQsIE1GR1BUX0haLA0KIAkJCQkJMHhGLCAw
eEZGRkUpOw0KKwlwcmludGsoS0VSTl9JTkZPIERSVl9OQU1FICI6IGNsb2Nr
ZXZlbnRzX2NvbmZpZ19hbmRfcmVnaXN0ZXIgcmV0dXJuZWRcbiIpOw0KKw0K
KwlwcmludGsoS0VSTl9JTkZPIERSVl9OQU1FICI6IGRpc2FibGluZyB2ZXJi
b3NlIGhhbmRsZXJcbiIpOw0KKwlXUklURV9PTkNFKHZlcmJvc2VfaGFuZGxl
ciwgMCk7DQogDQogCXJldHVybiAwOw0KIA0K

--546533125-1366019645-1507577618=:22810--