Расшифровка краха

[  121.145173] INFO: rcu_sched self-detected stall on CPU
[  121.155397] 	0-...: (1 GPs behind) idle=bd6/2/0 softirq=2552/2553 fqs=2991 
[  121.169232] 	 (t=6000 jiffies g=1283 c=1282 q=294)

Моя ванга говорит, что прерывание неправильно обработано. Но я так, мимо крокодил.

как то можно вычислить по данному логу, какое именно прерывание было обработано некорректно? И в догонку, можно (хотя бы абстрактный) пример того, как может быть некорректно обработано прерывание что бы вызвать крах?

Чуть конкретики: есть прерывание ethernet, в котором запускается шедуллер napi (для приёма пакетов по ethernet), все работает исправно (при небольшом количестве трафика), повышаем количество трафика (iperf) - хлоп, крах! Что в обработке прерывания могло вызвать крах? Может например ошибка в работе с памятью?

WARNING

А где крах-то?

[ 121.145173] INFO: rcu_sched self-detected stall on CPU

https://www.kernel.org/doc/Documentation/RCU/stallwarn.txt

Но я тоже ненастоящий сварщик.

Значит прерывание либо слишком часто срабатывает, либо слишком долго обрабатывается (поправьте если неверно понял).

Благодарю.Есть направление куда капать) я тоже совсем начинающий сварщик )

Краха не вижу, однако увиденное навевает нехорошие мысли о уарнинге по поводу переполнения стека.

Но это я так, к слову. Будучи ламерком в шестом поколении я даже навскидку не могу предполагать по поводу сабжевого описалова.

https://github.com/LibreELEC/linux-amlogic/blob/amlogic-3.10.y/kernel/smp.c#L...
отлаживаете ядро и не понимаете краха, вы точно тем в жизни занимаетесь ? может вам в чем то другом себя попробовать ? в пхп например

Только начинаю переползать с bare metal (stm32 и тд). Но задача вот такая передо мной. До недавнего времени неплохо справлялся, успешно портировал драйвер с 2.6.36.x под 4.14.x, etherne даже заработал, однако не смог выдавить более 500Mbt/s (вместо гигабита). Решено было переключить движок DMA с PDMA на QDMA (на нем обещается максимальная производительность) и тут затык - интерфейс работает, но при интенсивном обмене (трансмите в частности) такой вот варнинг + пропадает передача данных

При пропадании передачи данных по интерфейсу (до вываливания варнинга), аппаратные прерывания продолжают щелкать (во всяком случае в /proc/interrupts счетчик растет, и периодически вызывается обработчик), но в /proc/softirqs счетчик NET_RX перестает расти. об чем это может говорить?

/*
	 * Can deadlock when called with interrupts disabled.
	 * We allow cpu's that are not yet online though, as no one else can
	 * send smp call function interrupt to this cpu and as such deadlocks
	 * can't happen.
	 */
	WARN_ON_ONCE(cpu_online(this_cpu) && irqs_disabled()
		     && !oops_in_progress && !early_boot_irqs_disabled);

да и вообще прежде чем портировать или писать свои дрова, не плохо для начала посмотреть как это сделано в других

спасибо за наводку, уже понял что WARN_ON_ONCE - ключевой для меня макрос, гуглю по нему. но пока не вкурил, как это может мне помочь.

причем здесь макрос ? он запускает ваш трейс, а причина по которой он срабатывает у вас в исходниках
если вы не можете понять условия по которым он срабатывает, истинно вам говорю, бросайте это ядро и переходите на пхп

куда примерно капать?

Примерно в стакан.

Твой обработчик прерывания занимает слишком много времени, так что он сжирает весь CPU под нагрузкой. Без кода трудно сказать что именно там не так.

Первая возможная причина. Так же не отвергаю вариант некорректного доступа к памяти.

Навскидку, нет предположений, что могло смениться в ядре с 2.6.36.x к 4.14.x, что могло привести к таким последствиям, учитывая, что мною обработчик прерывания не правился + обработчик един для обоих движков DMA (считай режимов работы драйвера - PDMA и QDMA), а в режиме PDMA такого эффекта не наблюдается? Зато есть другой эффект, его я описывал выше - драйвер не выдает всю возможную пропускную способность упираясь в загрузку ЦП (top - 99%). Именно по-этому, повторюсь, решено было переключить на QDMA. Наверняка у обоих эффектов одна причина - низкая производительность драйвера, а именно

обработчик прерывания занимает слишком много времени

ты лучше код обработчика покажи, хули гадать. алсо повреждения памяти проявляются по-другому

определены:

CONFIG_RALINK_MT7621
CONFIG_RAETH_NAPI
CONFIG_RAETH_QDMA

/**
 * ei_interrupt - handle controler interrupt
 *
 * This routine is called at interrupt level in response to an interrupt from
 * the controller.
 *
 * RETURNS: N/A.
 */
#if LINUX_VERSION_CODE >= KERNEL_VERSION(2,6,21)
static irqreturn_t ei_interrupt(int irq, void *dev_id)
#else
static irqreturn_t ei_interrupt(int irq, void *dev_id, struct pt_regs * regs)
#endif
{
#if !defined(CONFIG_RAETH_NAPI)
	unsigned long reg_int_val = 0;
	unsigned long reg_int_val_p = 0;
	unsigned long reg_int_val_q = 0;
	unsigned long reg_int_mask=0;
	unsigned int recv = 0;
	unsigned int transmit __maybe_unused = 0;
	unsigned long flags;
#endif

	struct net_device *dev = (struct net_device *) dev_id;
	END_DEVICE *ei_local = netdev_priv(dev);

	//Qwert
	/*
	unsigned long old,cur,dcycle;
	static int cnt = 0;
	static unsigned long max_dcycle = 0,tcycle = 0;
	old = read_c0_count();
	*/
	if (dev == NULL)
	{
		printk (KERN_ERR "net_interrupt(): irq %x for unknown device.\n", irq_eth);
		return IRQ_NONE;
	}

#ifdef CONFIG_RAETH_NAPI
	gsw_delay_setting();
#if LINUX_VERSION_CODE > KERNEL_VERSION(2,6,35)
        if(napi_schedule_prep(&ei_local->napi)) {
#else
        if(netif_rx_schedule_prep(dev)) {
#endif
                atomic_inc(&ei_local->irq_sem);
		sysRegWrite(RAETH_FE_INT_ENABLE, 0);
#ifdef CONFIG_RAETH_QDMA		
		sysRegWrite(QFE_INT_ENABLE, 0);
#endif
#if LINUX_VERSION_CODE > KERNEL_VERSION(2,6,35)
		__napi_schedule(&ei_local->napi);
#else
                __netif_rx_schedule(dev);
#endif
        }
#else

	spin_lock_irqsave(&(ei_local->page_lock), flags);
	reg_int_val_p = sysRegRead(RAETH_FE_INT_STATUS);
#if defined(CONFIG_RAETH_INT_DBG)
	IntStatsUpdate(reg_int_val);
#endif	/* CONFIG_RAETH_INT_DBG */

#ifdef CONFIG_RAETH_QDMA	

	reg_int_val_q = sysRegRead(QFE_INT_STATUS);
#endif
	reg_int_val = reg_int_val_p | reg_int_val_q;
#if defined (DELAY_INT)
	if((reg_int_val & RX_DLY_INT))
		recv = 1;
	
	if (reg_int_val & RAETH_TX_DLY_INT)
		transmit = 1;

#if defined(CONFIG_RAETH_PDMA_DVT)
    raeth_pdma_lro_dly_int_dvt();
#endif  /* CONFIG_RAETH_PDMA_DVT */

#else
	if((reg_int_val & (RX_DONE_INT0 | RX_DONE_INT3 | RX_DONE_INT2 | RX_DONE_INT1)))
		recv = 1;

#if defined (CONFIG_RAETH_MULTIPLE_RX_RING)
#if defined(CONFIG_ARCH_MT7623)    
    if((reg_int_val & RX_DONE_INT3))
        recv = 3;

    if((reg_int_val & RX_DONE_INT2))
        recv = 2;

#endif  /* CONFIG_ARCH_MT7623 */
	if((reg_int_val & RX_DONE_INT1))
		recv = 1;
#endif

	if (reg_int_val & RAETH_TX_DONE_INT0)
		transmit |= RAETH_TX_DONE_INT0;

#if defined (CONFIG_RAETH_QOS)
	if (reg_int_val & TX_DONE_INT1)
		transmit |= TX_DONE_INT1;


	if (reg_int_val & TX_DONE_INT2)
		transmit |= TX_DONE_INT2;

	if (reg_int_val & TX_DONE_INT3)
		transmit |= TX_DONE_INT3;

#endif //CONFIG_RAETH_QOS

#endif //DELAY_INT

#ifdef CONFIG_RAETH_QDMA
	sysRegWrite(QFE_INT_STATUS, reg_int_val_q); 
#endif	

#if defined (CONFIG_RAETH_HW_LRO)
    if( reg_int_val & (ALT_RPLC_INT3 | ALT_RPLC_INT2 | ALT_RPLC_INT1) ){
        /* mask interrupts of rx flow to hw lor rings */
        reg_int_mask = sysRegRead(RAETH_FE_INT_ENABLE);
        sysRegWrite(RAETH_FE_INT_ENABLE, reg_int_mask & ~(ALT_RPLC_INT3 | ALT_RPLC_INT2 | ALT_RPLC_INT1));
        schedule_work(&ei_local->hw_lro_wq);
    }
#endif  /* CONFIG_RAETH_HW_LRO */

#if LINUX_VERSION_CODE > KERNEL_VERSION(3,10,0)
#if defined (CONFIG_RALINK_MT7620)|| defined (CONFIG_RALINK_MT7621) || defined(CONFIG_ARCH_MT7628)
	if(transmit)
		ei_xmit_housekeeping(0);
#else
	ei_xmit_housekeeping(0);
#endif		
#else
		ei_xmit_housekeeping(0);
#endif
    //QWERT
	sysRegWrite(RAETH_FE_INT_STATUS, reg_int_val_p);

	if (((recv == 1) || (pending_recv ==1)) && (tx_ring_full==0))
	{
		reg_int_mask = sysRegRead(RAETH_FE_INT_ENABLE);
#if defined (DELAY_INT)
		sysRegWrite(RAETH_FE_INT_ENABLE, reg_int_mask & ~(RX_DLY_INT));
#else
		sysRegWrite(RAETH_FE_INT_ENABLE, reg_int_mask & ~(RX_DONE_INT0 | RX_DONE_INT1 | RX_DONE_INT2 | RX_DONE_INT3));
#endif //DELAY_INT
#ifdef CONFIG_RAETH_QDMA		
		reg_int_mask = sysRegRead(QFE_INT_ENABLE);
#if defined (DELAY_INT)
		sysRegWrite(QFE_INT_ENABLE, reg_int_mask & ~(RX_DLY_INT));
#else
		sysRegWrite(QFE_INT_ENABLE, reg_int_mask & ~(RX_DONE_INT0 | RX_DONE_INT1 | RX_DONE_INT2 | RX_DONE_INT3));
#endif //DELAY_INT
#endif

		pending_recv=0;
#ifdef WORKQUEUE_BH
		schedule_work(&ei_local->rx_wq);
#else
#if defined (TASKLET_WORKQUEUE_SW)
		if (working_schedule == 1)
			schedule_work(&ei_local->rx_wq);
		else
#endif
		tasklet_hi_schedule(&ei_local->rx_tasklet);
#endif // WORKQUEUE_BH //
	} 
	else if (recv == 1 && tx_ring_full==1) 
	{
		pending_recv=1;
	}
	else if((recv == 0) && (transmit == 0))
	{
		gsw_delay_setting();
	}
	spin_unlock_irqrestore(&(ei_local->page_lock), flags);
#endif

	return IRQ_HANDLED;
}

для начала попробуй избавиться от spinlock

[ 121.178767] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.34 #0

Not tainted 4.14.34 #0

спасибо за наводку, почитаю в этом направлении.

а о чем говорит?

CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.34 #0

Так же обратил внимание, на статистику софт-прерывания

NET_RX: 15216 0 2 0

разве счетчики не должны расти равномерно (более или менее) на всех имеющихся ЦП? В чем может быть причина такого эффекта?

PID 0 - это самый важный, самый главный процесс, нулевой PID...

должны если у тебя 1) MSI/MSIX и прерывание забиндено на 4 ядра или просто 4 разных вектора по одному на пару колец. 2) Все 4 пары колец сконфигурены и активны. 3) Железяка распределяет фреймы по кольцам сама или настроена дисциплина распределения

swapper 0 - просто процесса в контексте которого отловлен затык, сам по себе он ничего не значит.

спасибо за разъяснения. это дополнило мое понимание работы системы.

что примечательно, при интенсивном обмене команда top показывает

CPU: 0% usr 0% sys 0% nic 75% idle 0% io 0% irq 25% sirq

что говорит (если я все верно понимаю) о том, что ЦП тратит всего 25% времени на софт прерывания и 75% на остальное.

похоже причина низкой производительности драйвера (в частности обработчика прерывания) - обработка одним CPU. Сейчас регистрация прерывания и обработчика осуществляется вызовом request_irq. Подозреваю, для включения MSI/MSIX необходимо регистрировать через devm_request_irq.

Для неравнодушных и последователей: проблему почти победил - повысить производительность драйвера удалось за счет распараллеливания обработки soft irq на 4 доступных ядра.

Это позволяет сделать RPS: пока что вручную в /sys/class/net/<device>/queues/<rx-queue>/rps_cpus прописал значение f вместо 0, что включает биты всех 4 ЦПУ (0 - означает отключенный RPS, ЦПУ обработавший прерывание, также обрабатывает пакет).

И вот я увидел долгожданный прирост счетчиков в /proc/softirqs

NET_RX: 50765 33979 40053 33367

при этом в /proc/interrupts

21: 1701 0 0 0 MIPS GIC 10 eth0

Осталось научить драйвер делать в это при создании интерфейса...

Для неравнодушных и последователей

Поздравляю!! Желаю дальнейших успехов!!!

Спасибо!

может кто нибудь подскажет, как заставить драйвер после создания интерфейса в /sys/class/net/<device>/queues/<rx-queue>/rps_cpus прописывать нужную мне битовую маску CPU ?

возьмите и изучите хотя бы один какой нибудь 10гб драйвер который есть в ядре

В общем никакой связи драйвера (в частности, структур типа struct net_device и тп.) со свойствами интерфейса не обнаружил (ни гуглением, ни код-ревьювом), поэтому эту настройку буду производить стартовым настроечным скриптом.