softirq: Per vector threading v2

So this set is in a testable state. I addressed preliminary reviews from Eric Dumazet, Paolo Abeni and Linus.

You may want to play with MAX_SOFTIRQ_RESTART value, which is now the number of calls allowed for a vector in a jiffy frame before it gets queued to the workqueue. I set it to the arbitrary value of 20 which is likely too low.

Also I'm not sure about the last patch. For example in the usecase of Dmitry Safonov it may be better not to apply it. I guess only testing and reviews can tell.

git://git.kernel.org/pub/scm/linux/kernel/git/frederic/linux-dynticks.git
softirq/thread

HEAD: 5a4c02b25bdcd853e3874d5319492ea6097f6e70

Thanks,
Frederic
---

Frederic Weisbecker (5):
softirq: Account time and iteration stats per vector
softirq: Per vector deferment to workqueue
softirq: Defer to workqueue when rescheduling is needed
softirq: Replace ksoftirqd with workqueues entirely
softirq: Reset vector call counter before workqueue completion

 Documentation/RCU/stallwarn.txt |   4 +-
 include/linux/interrupt.h       |   7 +-
 kernel/sched/cputime.c          |  12 +--
 kernel/sched/sched.h            |   4 +-
 kernel/softirq.c                | 232 +++++++++++++++++++++++++---------------
 net/ipv4/tcp_output.c           |   5 +-
 6 files changed, 161 insertions(+), 103 deletions(-)

As we plan to be able to defer some specific softirq vector processing to workqueues when those vectors need more time than IRQs can offer, let's first introduce the per-vector call counter/limit.

Each softirq vector is allowed to be called on IRQ tail at most MAX_SOFTIRQ_RESTART per jiffy. Once we reach that limit, the softirq processing is deferred to ksoftirqd. The threading will be divided to per vector worklets in further patches.

---
 kernel/softirq.c | 41 ++++++++++++++++++++++++++---------------
 1 file changed, 26 insertions(+), 15 deletions(-)

index 2f5e87f..e0f4b29 100644
@@ -62,6 +62,15 @@ const char * const softirq_to_name[NR_SOFTIRQS] = {
 	"TASKLET", "SCHED", "HRTIMER", "RCU"
 };
 
+struct vector {
+	unsigned int jiffy_calls;
+	unsigned long jiffy_snap;
+};
+
+static DEFINE_PER_CPU(struct vector, vector_cpu[NR_SOFTIRQS]) = {
+	[0 ... NR_SOFTIRQS-1] = { 0, INITIAL_JIFFIES }
+};
+
 /*
  * we cannot loop indefinitely here to avoid userspace starvation,
  * but we also don't want to introduce a worst case 1/HZ latency

@@ -192,19 +201,13 @@ EXPORT_SYMBOL(__local_bh_enable_ip);
 
 /*
  * We restart softirq processing for at most MAX_SOFTIRQ_RESTART times,
- * but break the loop if need_resched() is set or after 2 ms.
- * The MAX_SOFTIRQ_TIME provides a nice upper bound in most cases, but in
- * certain cases, such as stop_machine(), jiffies may cease to
- * increment and so we need the MAX_SOFTIRQ_RESTART limit as
- * well to make sure we eventually return from this method.
- *
+ * but break the loop if need_resched() is set.
  * These limits have been established via experimentation.
  * The two things to balance is latency against fairness -
  * we want to handle softirqs as soon as possible, but they
  * should not be able to lock up the box.
  */
-#define MAX_SOFTIRQ_TIME  msecs_to_jiffies(2)
-#define MAX_SOFTIRQ_RESTART 10
+#define MAX_SOFTIRQ_RESTART 20
 
 #ifdef CONFIG_TRACE_IRQFLAGS
 /*

@@ -241,12 +244,10 @@ static inline void lockdep_softirq_end(bool in_hardirq) { }
 
 asmlinkage __visible void __softirq_entry __do_softirq(void)
 {
-	unsigned long end = jiffies + MAX_SOFTIRQ_TIME;
 	unsigned long old_flags = current->flags;
-	int max_restart = MAX_SOFTIRQ_RESTART;
 	struct softirq_action *h;
 	bool in_hardirq;
-	__u32 pending;
+	__u32 pending, overrun = 0;
 	int softirq_bit;
 
 	/*

@@ -271,6 +272,7 @@ asmlinkage __visible void __softirq_entry __do_softirq(void)
 	h = softirq_vec;
 
 	while ((softirq_bit = ffs(pending))) {
+		struct vector *vector;
 		unsigned int vec_nr;
 		int prev_count;
 

@@ -284,6 +286,16 @@ asmlinkage __visible void __softirq_entry __do_softirq(void)
 		trace_softirq_entry(vec_nr);
 		h->action(h);
 		trace_softirq_exit(vec_nr);
+
+		vector = this_cpu_ptr(&vector_cpu[vec_nr]);
+		if (time_before(vector->jiffy_snap, jiffies)) {
+			vector->jiffy_calls = 0;
+			vector->jiffy_snap = jiffies;
+		}
+
+		if (++vector->jiffy_calls > MAX_SOFTIRQ_RESTART)
+			overrun |= 1 << vec_nr;
+
 		if (unlikely(prev_count != preempt_count())) {
 			pr_err("huh, entered softirq %u %s %p with preempt_count %08x, exited with %08x?\n",
 			       vec_nr, softirq_to_name[vec_nr], h->action,

@@ -299,11 +311,10 @@ asmlinkage __visible void __softirq_entry __do_softirq(void)
 
 	pending = local_softirq_pending();
 	if (pending) {
-		if (time_before(jiffies, end) && !need_resched() &&
-		    --max_restart)
+		if (overrun || need_resched())
+			wakeup_softirqd();
+		else
 			goto restart;
-
-		wakeup_softirqd();
 	}
 
 	lockdep_softirq_end(in_hardirq);

2.7.4

Some softirq vectors can be more CPU hungry than others. Especially networking may sometimes deal with packet storm and need more CPU than IRQ tail can offer without inducing scheduler latencies. In this case the current code defers to ksoftirqd that behaves nicer. Now this nice behaviour can be bad for other IRQ vectors that usually need quick processing.

To solve this we only defer to threading the vectors that outreached the calls limit on IRQ tail processing and leave the others inline on real Soft-IRQs service. This is achieved using workqueues with per-CPU/per-vector worklets.

Note ksoftirqd is not yet removed as it is still needed for threaded IRQs mode.

---
 include/linux/interrupt.h |   2 +
 kernel/sched/cputime.c    |   5 +-
 kernel/softirq.c          | 121 +++++++++++++++++++++++++++++++++++++++++-----
 net/ipv4/tcp_output.c     |   3 +-
 4 files changed, 117 insertions(+), 14 deletions(-)

index 69c2382..92d044d 100644
@@ -514,6 +514,8 @@ static inline struct task_struct *this_cpu_ksoftirqd(void)
 	return this_cpu_read(ksoftirqd);
 }
 
+extern int softirq_serving_workqueue(void);
+
 /* Tasklets --- multithreaded analogue of BHs.
 
    Main feature differing them of generic softirqs: tasklet

index bac6ac9..30f70e5 100644
@@ -71,7 +71,8 @@ void irqtime_account_irq(struct task_struct *curr)
 	 */
 	if (hardirq_count())
 		irqtime_account_delta(irqtime, delta, CPUTIME_IRQ);
-	else if (in_serving_softirq() && curr != this_cpu_ksoftirqd())
+	else if (in_serving_softirq() && curr != this_cpu_ksoftirqd() &&
+		 !softirq_serving_workqueue())
 		irqtime_account_delta(irqtime, delta, CPUTIME_SOFTIRQ);
 }
 EXPORT_SYMBOL_GPL(irqtime_account_irq);

@@ -375,7 +376,7 @@ static void irqtime_account_process_tick(struct task_struct *p, int user_tick,
 
 	cputime -= other;
 
-	if (this_cpu_ksoftirqd() == p) {
+	if (this_cpu_ksoftirqd() == p || softirq_serving_workqueue()) {
 		/*
 		 * ksoftirqd time do not get accounted in cpu_softirq_time.
 		 * So, we have to handle it separately here.

index a4d214c..b4e4160 100644
@@ -919,7 +919,8 @@ void tcp_wfree(struct sk_buff *skb)
 	 * - chance for incoming ACK (processed by another cpu maybe)
 	 *   to migrate this flow (skb->ooo_okay will be eventually set)
 	 */
-	if (refcount_read(&sk->sk_wmem_alloc) >= SKB_TRUESIZE(1) && this_cpu_ksoftirqd() == current)
+	if (refcount_read(&sk->sk_wmem_alloc) >= SKB_TRUESIZE(1) &&
+	    (this_cpu_ksoftirqd() == current || softirq_serving_workqueue()))
 		goto out;
 
 	for (oval = READ_ONCE(sk->sk_tsq_flags);; oval = nval) {

2.7.4

One more step toward converting ksoftirqd to per vector workqueues.

---
 kernel/softirq.c | 18 ++++++++----------
 1 file changed, 8 insertions(+), 10 deletions(-)

index 255da68..441e654 100644
@@ -389,16 +389,14 @@ asmlinkage __visible void __softirq_entry __do_softirq(void)
 
 	pending = local_softirq_pending() & ~softirq->pending_work_mask;
 	if (pending) {
-		if (need_resched()) {
-			wakeup_softirqd();
-		} else {
-			/* Vectors that overreached the limits are threaded */
-			if (overrun & pending)
-				do_softirq_workqueue(overrun & pending);
-			pending &= ~overrun;
-			if (pending)
-				goto restart;
-		}
+		if (need_resched())
+			overrun = pending;
+		/* Vectors that overreached the limits are threaded */
+		if (overrun & pending)
+			do_softirq_workqueue(overrun & pending);
+		pending &= ~overrun;
+		if (pending)
+			goto restart;
 	}
 
 	lockdep_softirq_end(in_hardirq);

2.7.4

Ksoftirqd only remains to implement threaded IRQs. Convert it to existing per-vector workqueues to avoid code duplication.

---
 Documentation/RCU/stallwarn.txt |  4 +-
 include/linux/interrupt.h       |  7 ----
 kernel/sched/cputime.c          | 13 +++---
 kernel/sched/sched.h            |  4 +-
 kernel/softirq.c                | 87 +++++++++--------------------------------
 net/ipv4/tcp_output.c           |  4 +-
 6 files changed, 31 insertions(+), 88 deletions(-)

index a08f928..ea3a8de 100644
@@ -17,8 +17,8 @@ o	A CPU looping in an RCU read-side critical section.
 o	A CPU looping with interrupts disabled.
 
 o	A CPU looping with preemption disabled.  This condition can
-	result in RCU-sched stalls and, if ksoftirqd is in use, RCU-bh
-	stalls.
+	result in RCU-sched stalls and, if softirq workqueue is in use,
+	RCU-bh stalls.
 
 o	A CPU looping with bottom halves disabled.  This condition can
 	result in RCU-sched and RCU-bh stalls.

index 92d044d..680f620 100644
@@ -507,13 +507,6 @@ extern void __raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq_irqoff(unsigned int nr);
 extern void raise_softirq(unsigned int nr);
 
-DECLARE_PER_CPU(struct task_struct *, ksoftirqd);
-
-static inline struct task_struct *this_cpu_ksoftirqd(void)
-{
-	return this_cpu_read(ksoftirqd);
-}
-
 extern int softirq_serving_workqueue(void);
 
 /* Tasklets --- multithreaded analogue of BHs.

index 30f70e5..c5b8dbd 100644
@@ -64,15 +64,14 @@ void irqtime_account_irq(struct task_struct *curr)
 	irqtime->irq_start_time += delta;
 
 	/*
-	 * We do not account for softirq time from ksoftirqd here.
-	 * We want to continue accounting softirq time to ksoftirqd thread
+	 * We do not account for softirq time from workqueue here.
+	 * We want to continue accounting softirq time to workqueue thread
 	 * in that case, so as not to confuse scheduler with a special task
 	 * that do not consume any time, but still wants to run.
 	 */
 	if (hardirq_count())
 		irqtime_account_delta(irqtime, delta, CPUTIME_IRQ);
-	else if (in_serving_softirq() && curr != this_cpu_ksoftirqd() &&
-		 !softirq_serving_workqueue())
+	else if (in_serving_softirq() && !softirq_serving_workqueue())
 		irqtime_account_delta(irqtime, delta, CPUTIME_SOFTIRQ);
 }
 EXPORT_SYMBOL_GPL(irqtime_account_irq);

@@ -376,11 +375,11 @@ static void irqtime_account_process_tick(struct task_struct *p, int user_tick,
 
 	cputime -= other;
 
-	if (this_cpu_ksoftirqd() == p || softirq_serving_workqueue()) {
+	if (softirq_serving_workqueue()) {
 		/*
-		 * ksoftirqd time do not get accounted in cpu_softirq_time.
+		 * Softirq wq time do not get accounted in cpu_softirq_time.
 		 * So, we have to handle it separately here.
-		 * Also, p->stime needs to be updated for ksoftirqd.
+		 * Also, p->stime needs to be updated for workqueue.
 		 */
 		account_system_index_time(p, cputime, CPUTIME_SOFTIRQ);
 	} else if (user_tick) {

index b19552a2..5d481f1 100644
@@ -2061,8 +2061,8 @@ struct irqtime {
 DECLARE_PER_CPU(struct irqtime, cpu_irqtime);
 
 /*
- * Returns the irqtime minus the softirq time computed by ksoftirqd.
- * Otherwise ksoftirqd's sum_exec_runtime is substracted its own runtime
+ * Returns the irqtime minus the softirq time computed by workqueue.
+ * Otherwise workqueue's sum_exec_runtime is substracted its own runtime
  * and never move forward.
  */
 static inline u64 irq_time_read(int cpu)

index b4e4160..3b4811e 100644
@@ -912,7 +912,7 @@ void tcp_wfree(struct sk_buff *skb)
 	 */
 	WARN_ON(refcount_sub_and_test(skb->truesize - 1, &sk->sk_wmem_alloc));
 
-	/* If this softirq is serviced by ksoftirqd, we are likely under stress.
+	/* If this softirq is serviced by workqueue, we are likely under stress.
 	 * Wait until our queues (qdisc + devices) are drained.
 	 * This gives :
 	 * - less callbacks to tcp_write_xmit(), reducing stress (batches)

@@ -920,7 +920,7 @@ void tcp_wfree(struct sk_buff *skb)
 	 *   to migrate this flow (skb->ooo_okay will be eventually set)
 	 */
 	if (refcount_read(&sk->sk_wmem_alloc) >= SKB_TRUESIZE(1) &&
-	    (this_cpu_ksoftirqd() == current || softirq_serving_workqueue()))
+	    softirq_serving_workqueue())
 		goto out;
 
 	for (oval = READ_ONCE(sk->sk_tsq_flags);; oval = nval) {

2.7.4

Once a softirq vector queue has been completed from the workqueue, its call counter for the current jiffy frame can be reset in order to handle those that will follow from the normal IRQ tail softirq processing.

---
 kernel/softirq.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

index b2a5384..4e5a0ef 100644
@@ -255,10 +255,13 @@ static void vector_work_func(struct work_struct *work)
 	local_irq_disable();
 
 	pending = local_softirq_pending();
-	if (pending & vec_bit)
+	if (pending & vec_bit) {
 		schedule_work_on(smp_processor_id(), &vector->work);
-	else
+	} else {
 		softirq->pending_work_mask &= ~vec_bit;
+		vector->jiffy_calls = 0;
+		vector->jiffy_snap = jiffies;
+	}
 
 	lockdep_softirq_exit();
 	account_irq_exit_time(current);

2.7.4

Em Tue, 16 Jan 2018 05:40:35 +0100
Frederic Weisbecker <[email protected]> escreveu:

Hi Frederic,

As reported on a separate thread:

	http://lkml.iu.edu/hypermail/linux/kernel/1801.1/00110.html

The current approach taken since Kernel 4.9 by this patch:

	https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=4cd13c21b207e80ddb1144c576500098f2d5f882

Broke applications that record a digital TV channel.

The bug is easily reproductible on RPi3 with LibreELEC and tvheadend (with both RPi downstram Kernel and with upstream Kernel 4.15-rc7).

Your patchset seems to be better addressing the softirq needs, by only deferring processing when really needed, instead of always doing it.

I'm now testing if it fixes the issues with the media subsystem.

All tests below were done on a Raspberry Pi3 with a SanDisk Extreme U3 microSD card with 32GB and a DVBSky S960C DVB-S2 tuner with an external power supply, connected to a TCP/IP network via Ethernet (with uses USB on RPi). It also have a serial cable connected to it.

On both systems, I'm running Kernel 4.15-rc7 + your patches from this branch:
https://git.linuxtv.org/mchehab/experimental.git/log/?h=softirq_fixup

TEST 1: Raspbian with v4l-utils
===============================

I booted RPi3 on a raspbian partition and installed v4l-utils from its git tree.

I added support at v4l-utils[1] to parse MPEG-TS continuity sequence number on monitor mode.

[1] https://git.linuxtv.org/v4l-utils.git/

Before testing on RPi3, I double-checked the new discontinuity detector several times on an i7core machine, to be sure that it won't be producing false alarms, while it would be detecting and reporting discontinuities when they happens.

On my tests, it is recording MPEG-TS data at ~60Mbits/s.

On this test, it seems that your patchset addresses the issue.

This is the results with your patchset and CONFIG_HZ=100:

 $ rm out.ts; dvbv5-zap -l universal -c ~/vivo-channels.conf NBR -m -X 300 -t 300 -o out.ts 2>errors

62.67s: Starting capture
206.82s: pid 2064, expecting 1 received 6
362.70s: Stopping capture

PID FREQ SPEED TOTAL

   18   1439.01 p/s   2113.5 Kbps    79260 KB
 1901    933.19 p/s   1370.6 Kbps    51400 KB
 1911   1250.57 p/s   1836.8 Kbps    68881 KB
 1921   1280.59 p/s   1880.9 Kbps    70534 KB
 1931   1382.41 p/s   2030.4 Kbps    76143 KB
 1941    837.57 p/s   1230.2 Kbps    46133 KB
 1951    531.91 p/s    781.2 Kbps    29297 KB
 1961    531.91 p/s    781.2 Kbps    29297 KB
 1971    866.72 p/s   1273.0 Kbps    47738 KB
 1991   1187.88 p/s   1744.7 Kbps    65428 KB
 2001    784.59 p/s   1152.4 Kbps    43214 KB
 2011    770.16 p/s   1131.2 Kbps    42420 KB
 2031   1925.98 p/s   2828.8 Kbps   106082 KB
 2041    851.09 p/s   1250.0 Kbps    46877 KB
 2051    812.99 p/s   1194.1 Kbps    44779 KB
 2061    847.85 p/s   1245.3 Kbps    46699 KB
 2071   1416.26 p/s   2080.1 Kbps    78007 KB
 2081   1411.99 p/s   2073.9 Kbps    77771 KB
 2091    531.91 p/s    781.2 Kbps    29297 KB
 2101    531.91 p/s    781.2 Kbps    29297 KB
 2111   1287.53 p/s   1891.1 Kbps    70917 KB
 2131    845.45 p/s   1241.8 Kbps    46567 KB
 2141    870.95 p/s   1279.2 Kbps    47971 KB
 2151   2451.17 p/s   3600.2 Kbps   135009 KB
 2161    854.14 p/s   1254.5 Kbps    47045 KB
 2171   1211.97 p/s   1780.1 Kbps    66754 KB

2191 7313.75 p/s 10742.1 Kbps 402837 KB
8191 751.47 p/s 1103.7 Kbps 41390 KB
OTHER 3793.81 p/s 5572.2 Kbps 208961 KB 1 continuity errors
TOT 39506.70 p/s 58025.5 Kbps 2176006 KB

Lock (0x1f) Signal= -66.52dBm C/N= 14.31dB postBER= 0

Having just a single continuity error on 300 seconds seems acceptable (and it could be unrelated to Kernel handling).

TEST 2
======

I booted a partition with LibreELEC 8.2.2 and tvheadend backend.

I'm recording one MPEG-TS service/"channel" composed of one audio and one video stream, while playing the same video twice via network, using VLC.

The total traffic collected by tvheadend was about 4 Mbits/s (audio+video+EPG tables). It is part of a 58 mbits/s MPEG Transport stream, with 23 TV service/"channels" on it.

On LibreELEC, I'm now seeing those logs, just after boot:

[    9.262681] usb 1-1.4: DVB: adapter 0 frontend 0 frequency 0 out of range (950000..2150000)
[    9.330306] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1
[   13.282765] NOHZ: local_softirq_pending 08
[   13.331928] NOHZ: local_softirq_pending 08
[   13.480830] NOHZ: local_softirq_pending 08
[   13.531364] NOHZ: local_softirq_pending 40
[   13.820693] NOHZ: local_softirq_pending 08
[   13.868430] NOHZ: local_softirq_pending 08
[   14.088503] NOHZ: local_softirq_pending 08
[   16.137247] NOHZ: local_softirq_pending 08

I ran libreELEC for about one hour there, and got those errors:

Jan 17 15:42:53 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 3)
Jan 17 15:44:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 5)
Jan 17 15:44:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 1)
Jan 17 15:45:11 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 6)
Jan 17 15:45:21 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 2)
Jan 17 15:45:25 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 8)
Jan 17 15:45:59 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 10)
Jan 17 15:45:59 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 5)
Jan 17 15:47:39 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 11)
Jan 17 15:47:39 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 6)
Jan 17 15:49:56 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 12)
Jan 17 15:50:07 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 13)
Jan 17 15:50:33 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 14)
Jan 17 15:50:35 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 7)
Jan 17 15:50:46 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 16)
Jan 17 15:50:46 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 8)
Jan 17 15:51:06 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 17)
Jan 17 15:54:14 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 18)
Jan 17 15:54:14 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 9)
Jan 17 15:58:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 21)
Jan 17 15:58:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 10)
Jan 17 15:59:00 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 22)
Jan 17 16:01:53 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 23)
Jan 17 16:01:53 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 11)
Jan 17 16:02:13 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 24)
Jan 17 16:02:13 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 12)
Jan 17 16:02:23 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 25)
Jan 17 16:03:03 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 26)
Jan 17 16:03:13 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 28)
Jan 17 16:04:24 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 29)
Jan 17 16:04:24 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 13)
Jan 17 16:07:42 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 30)
Jan 17 16:08:52 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 31)
Jan 17 16:09:20 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 32)
Jan 17 16:09:21 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 14)
Jan 17 16:10:30 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 34)
Jan 17 16:11:02 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 35)
Jan 17 16:11:02 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 15)
Jan 17 16:13:31 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 37)
Jan 17 16:14:01 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 38)
Jan 17 16:14:29 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 39)
Jan 17 16:18:58 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 40)
Jan 17 16:18:58 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 16)
Jan 17 16:19:19 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 41)
Jan 17 16:19:43 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 42)
Jan 17 16:19:43 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 17)
Jan 17 16:20:19 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 43)
Jan 17 16:20:19 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 18)
Jan 17 16:20:39 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 19)
Jan 17 16:21:41 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 44)
Jan 17 16:22:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 45)
Jan 17 16:22:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 20)
Jan 17 16:22:18 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 46)
Jan 17 16:25:18 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 47)
Jan 17 16:25:18 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 21)
Jan 17 16:25:58 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 48)
Jan 17 16:26:14 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 49)
Jan 17 16:26:14 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 22)
Jan 17 16:26:53 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 50)
Jan 17 16:26:53 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 23)
Jan 17 16:27:13 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 51)
Jan 17 16:28:03 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 52)
Jan 17 16:28:33 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 53)
Jan 17 16:28:33 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 24)
Jan 17 16:28:37 rpi3 kernel: [ 2918.072789] alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: [ 2918.075609] alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: [ 2918.078281] alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: [ 2918.124162] alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:37 rpi3 kernel: alloc_contig_range: [2a844, 2a845) PFNs busy
Jan 17 16:28:45 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 55)
Jan 17 16:29:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 56)
Jan 17 16:29:05 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 25)
Jan 17 16:30:15 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 57)
Jan 17 16:30:31 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 58)
Jan 17 16:30:31 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 26)
Jan 17 16:30:54 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 59)
Jan 17 16:31:21 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 61)
Jan 17 16:31:25 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 27)
Jan 17 16:32:31 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 63)
Jan 17 16:32:31 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 28)
Jan 17 16:35:44 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 64)
Jan 17 16:37:00 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 65)
Jan 17 16:37:00 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 29)
Jan 17 16:37:13 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 67)
Jan 17 16:37:13 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 30)
Jan 17 16:37:49 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 68)
Jan 17 16:38:09 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 69)
Jan 17 16:38:39 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 70)
Jan 17 16:39:09 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 71)
Jan 17 16:39:09 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 31)
Jan 17 16:39:44 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 72)
Jan 17 16:39:44 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 32)
Jan 17 16:40:06 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 73)
Jan 17 16:40:06 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 33)
Jan 17 16:40:48 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 77)
Jan 17 16:40:48 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 35)
Jan 17 16:41:28 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 78)
Jan 17 16:41:58 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 79)
Jan 17 16:41:58 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 36)
Jan 17 16:42:17 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 80)
Jan 17 16:42:29 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 81)
Jan 17 16:42:29 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 37)
Jan 17 16:42:47 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 83)
Jan 17 16:42:47 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 38)
Jan 17 16:43:26 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 84)
Jan 17 16:44:46 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 85)
Jan 17 16:44:46 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 39)
Jan 17 16:45:10 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 86)
Jan 17 16:45:10 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 40)
Jan 17 16:46:45 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 88)
Jan 17 16:47:32 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 89)
Jan 17 16:47:32 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 41)
Jan 17 16:48:17 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 90)
Jan 17 16:48:17 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 42)
Jan 17 16:48:53 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 92)
Jan 17 16:49:23 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 93)
Jan 17 16:50:03 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: H264 @ #1911 Continuity counter error (total 94)
Jan 17 16:50:03 rpi3 tvheadend[238]: TS: DVB-S Network/12130H/NBR: MPEG2AUDIO @ #1912 Continuity counter error (total 43)

capture USB stick. On the tests I ran before, either reverting changeset

	https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=4cd13c21b207e80ddb1144c576500098f2d5f882
or applying this fixup:
	https://git.linuxtv.org/mchehab/experimental.git/commit/?h=softirq_fixup&id=7996c39af87d329f64e6b1b2af120d6ce11ede29

it got better results.

I intend to do further tests on it. Do you have some procedure to better test it?

Thanks,
Mauro

Hi Mauro,

I see, so you may want to test (possibly much) higher values of MAX_SOFTIRQ_RESTART, such as 50 or 100.

We are now setting call limits per jiffy frame. Perhaps I should still keep limits per do_softirq() calls as well and couple both.

Thanks for testing this!

I suspect the "number of softiqs per jiffy" is hardly interesting at all.

We used to allow up to 2mS or ten iterations per _invocation_, never mind per timer tick.

I thought you were going to actally account for time, but I don't think you ended up doing that.

Maybe time isn't necessarily the thing to do, but just pure "count per jiffy" seems very bad.

What I might suggest using instead:

- do it by time. This may be too expensive, though. Keeping track of
ns-level timing per invocation can be nasty.

- do it by "we got a new softirq event while handling another softirq
event". That was our old count per invocation, except you could do it per softirq, and just allow *one* (ie keep a bitmask of "I've already handled this softirq", and if the restart results in it being triggered *again* you say "ok, I'll just move this to a workqueue"

- .. something else?

I'd suggest trying the "if we get a new softirq event that we've already seen while we were already handling softirq events" thing. That should really take care of the networking case of "90% time spend in softirq handling during packet storms" thing. If we spend that much time on softirqs, we *will* get a new softirq while handling an old one occasionally.

Linus

I did in the first version but then I thought you suggested that count per jiffy. I probably misunderstood :)

Indeed, the more I think about it, the more doubts I have too. At least I started to think that this metric alone is not enough.

Yeah I would like to avoid that if we can. I guess it's ok if it sums up to rdtsc but I fear it's common to have a heavier version.

That one is very tempting.

Ok I'm going to try that for the v3.

Thanks.

Oh, miscommunication.

I tried to suggest to do things purely by time (from an accounting standpoint), but then to also have some "minimum time" for each invocation, so that there effectively ends up being an invocation limit too.

Honestly, that's mainly because I worry about just how good the time-based approach might be (ie some hardware doesn't have a good high-frequency clock to read etc.

On x86-64, the TSC would be fairly natural as a clock, but we support architectures without anything like that, so time-based definitely has some issues.

But thinking about it more, I do end up liking my suggested "just keep a bitmap of softirqs that have been handled" thing, and kick the softirq to a thread if it ever seems to get into that "we already saw this one".

It might just work very naturally, and it sure as hell is simple and has no subtle interactions with the granularity of whatever random clock the architecture or platform has.

It should never trigger under any normal load, but I think it *should* trigger under the load that the networking people worry about. If you get a flood of UDP packets, and spend a lot of time in softirqs, I'm pretty sure you'd hit that case of seeing the same softirq re-raised fairly naturally and quickly.

Linus

Ah ok I see.

Yeah indeed, there is that too. Performance and reliability.

Ok after a quick tracing check, it seems that executing the same softirq vector twice in the same interrupt does not happen without much stress.

I'm trying that solution and we'll see what testing will reveal from people's boxes.

Thanks.

Uhm, yes it should.. but that was what I originally saw on hw - that raising a new softirq under UDP packet storm might happen slower than expected. And a new softirq is raised only after the first one was processed. Which results in rare deferring.

            Dima