From mboxrd@z Thu Jan 1 00:00:00 1970 From: =?UTF-8?Q?Mattias_R=c3=b6nnblom?= Subject: Re: DSW eventdev is getting "stuck"? Date: Thu, 4 Apr 2019 09:39:50 +0200 Message-ID: <7790bc0b-8c70-fa82-8d34-ba25dbaf226e@ericsson.com> References: <3353B035-E890-4753-8863-5647DFE61E23@paloaltonetworks.com> <8510f66d-a63e-4ef9-44e1-071758fec6fd@ericsson.com> <3B32DEF7-8563-4BB5-BB01-0BFE29277B37@paloaltonetworks.com> <2fd8bee9-a375-95b7-eb96-eef8b59e531d@ericsson.com> <83449720-1B93-4C96-8CF0-7F5753D1F0AA@paloaltonetworks.com> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit To: Venky Venkatesh , "dev@dpdk.org" Return-path: Received: from mail.lysator.liu.se (mail.lysator.liu.se [130.236.254.3]) by dpdk.org (Postfix) with ESMTP id AACCE5A4A for ; Thu, 4 Apr 2019 09:39:54 +0200 (CEST) Received: from mail.lysator.liu.se (localhost [127.0.0.1]) by mail.lysator.liu.se (Postfix) with ESMTP id 182D440005 for ; Thu, 4 Apr 2019 09:39:54 +0200 (CEST) In-Reply-To: <83449720-1B93-4C96-8CF0-7F5753D1F0AA@paloaltonetworks.com> Content-Language: en-US List-Id: DPDK patches and discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: dev-bounces@dpdk.org Sender: "dev" On 2019-04-04 07:39, Venky Venkatesh wrote: > > > On 4/3/19, 12:02 PM, "Mattias Rönnblom" wrote: > > On 2019-04-03 20:36, Venky Venkatesh wrote: > > > > > > On 4/3/19, 11:34 AM, "Mattias Rönnblom" wrote: > > > > On 2019-04-03 20:17, Venky Venkatesh wrote: > > > Hi, > > > I am using the DSW code from 18.11 with the default settings for all the #defines. Here are some more details: > > > I have an 8 port system with 1 queue. > > > All ports can inject events. Port 0 and 7 inject events rarely. > > > Ports 1-6 are linked to the queue and hence dequeue events. > > > > > > I see that in steady state the total number enqueues into the system is much greater than the total number of dequeues. > > > eventdev deq#: 1948491 enq#: 1949007 > > > > > > > If you have more enqueues than dequeues, it means there are events in > > flight in the scheduler. In the above case, it's roughly 516 events, > > which sounds perfectly healthy and normal. I say roughly, because > > there's no way to take a consistent, global snapshot of all xstats counters. > > > > [VV]: This is in steady state i.e. there are no more events being injected into the system. So shouldn’t everything get drained out at some point? > > > > Assuming appropriate application behavior, sure, of course. > > Events in flight are either in the output buffer on the producer port, > or the input ring on the consumer. > > Inappropriate behavior would be if any port (producer, consumer or > producer+consumer) is left unattended (i.e. no enqueue or dequeue > operation is performed). > > [VV]: I am pasting the original data again below. If about 516 events are inflight, atleast a few should show up in one of the data structures that you refer to -- but they don’t as seen below. Isn't that odd? Do you have any other places I can look -- there were no migrations too to look at some other transient buffers. > > Below are the counters: > > [root@PA-VM-venky ~]# cat y > dev_credits_on_loan: 883 > ------ port 0 -------- > port_0_new_enqueued: 125 > port_0_forward_enqueued: 0 > port_0_release_enqueued: 0 > port_0_queue_0_enqueued: 125 > port_0_dequeued: 0 > port_0_queue_0_dequeued: 0 > port_0_migrations: 0 Zero migrations? Looks suspicions, unless you've had a very light load throughout the duration of the test. > port_0_migration_latency: 0 > port_0_event_proc_latency: 0 > port_0_inflight_credits: 3 > port_0_load: 49 > port_0_last_bg: 39368511869708 This is an unattended port. "last_bg" is a timestamp of when this port last checked for ongoing "background operations" (included just for the purpose of finding offending ports). A background operation is handling the signaling required for migration to progress, or flushing the output buffers - for producers going idle. If you compare this "last_bg" the others', you'll see that this port has been idle for something like 3.8e+13 TSC cycles. Assuming 2,4 GHz TSC clock, this port hasn't received any love in ~4h. An unattended port blocks completion of a migration. This in turn means that there might well be events sitting in the "paused_events" array at the various ports, related to the in-progress migration. Check "paused_events_len" in gdb to verify that this is indeed the case. > ------ port 1 -------- > port_1_new_enqueued: 138947 > port_1_forward_enqueued: 237896 > port_1_release_enqueued: 0 > port_1_queue_0_enqueued: 376843 > port_1_dequeued: 475778 > port_1_queue_0_dequeued: 475778 > port_1_migrations: 0 > port_1_migration_latency: 0 > port_1_event_proc_latency: 119069 > port_1_inflight_credits: 13 > port_1_load: 0 > port_1_last_bg: 77183632541672 > ------ port 2 -------- > port_2_new_enqueued: 88834 > port_2_forward_enqueued: 156687 > port_2_release_enqueued: 0 > port_2_queue_0_enqueued: 245521 > port_2_dequeued: 313358 > port_2_queue_0_dequeued: 313358 > port_2_migrations: 0 > port_2_migration_latency: 0 > port_2_event_proc_latency: 176184 > port_2_inflight_credits: 15 > port_2_load: 0 > port_2_last_bg: 77183632941696 > ------ port 3 -------- > port_3_new_enqueued: 73170 > port_3_forward_enqueued: 78087 > port_3_release_enqueued: 0 > port_3_queue_0_enqueued: 151257 > port_3_dequeued: 165317 > port_3_queue_0_dequeued: 165317 > port_3_migrations: 0 > port_3_migration_latency: 0 > port_3_event_proc_latency: 329601 > port_3_inflight_credits: 66 > port_3_load: 0 > port_3_last_bg: 77183632966910 > ------ port 4 -------- > port_4_new_enqueued: 93182 > port_4_forward_enqueued: 76422 > port_4_release_enqueued: 0 > port_4_queue_0_enqueued: 169604 > port_4_dequeued: 207721 > port_4_queue_0_dequeued: 207721 > port_4_migrations: 0 > port_4_migration_latency: 0 > port_4_event_proc_latency: 262259 > port_4_inflight_credits: 114 > port_4_load: 0 > port_4_last_bg: 77183632760588 > ------ port 5 -------- > port_5_new_enqueued: 144855 > port_5_forward_enqueued: 630897 > port_5_release_enqueued: 0 > port_5_queue_0_enqueued: 775752 > port_5_dequeued: 633700 > port_5_queue_0_dequeued: 633700 > port_5_migrations: 0 > port_5_migration_latency: 0 > port_5_event_proc_latency: 88203 > port_5_inflight_credits: 64 > port_5_load: 0 > port_5_last_bg: 77183632277448 > ------ port 6 -------- > port_6_new_enqueued: 153590 > port_6_forward_enqueued: 76315 > port_6_release_enqueued: 0 > port_6_queue_0_enqueued: 229905 > port_6_dequeued: 152617 > port_6_queue_0_dequeued: 152617 > port_6_migrations: 0 > port_6_migration_latency: 0 > port_6_event_proc_latency: 354408 > port_6_inflight_credits: 92 > port_6_load: 0 > port_6_last_bg: 77183632653092 > ------ port 7 -------- > port_7_new_enqueued: 0 > port_7_forward_enqueued: 0 > port_7_release_enqueued: 0 > port_7_queue_0_enqueued: 0 > port_7_dequeued: 0 > port_7_queue_0_dequeued: 0 > port_7_migrations: 0 > port_7_migration_latency: 0 > port_7_event_proc_latency: 0 > port_7_inflight_credits: 0 > port_7_load: 0 Where's the "last_bg" for this port? > > > > Below are the data structure values: > > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[0]->out_buffer_len > $2 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[1]->out_buffer_len > $3 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[2]->out_buffer_len > $4 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[3]->out_buffer_len > $5 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[4]->out_buffer_len > $6 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[5]->out_buffer_len > $7 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[6]->out_buffer_len > $8 = {0 } > (gdb) p ((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[7]->out_buffer_len > $9 = {0 } > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[0]->in_ring > $10 = {r = {name = "dsw0_p0", '\000' , flags = 6, memzone = 0xc000000090, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 0, tail = 0, > single = 0}, pad1 = 0 '\000', cons = {head = 0, tail = 0, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[1]->in_ring > $11 = {r = {name = "dsw0_p1", '\000' , flags = 6, memzone = 0xc000000120, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 475778, > tail = 475778, single = 0}, pad1 = 0 '\000', cons = {head = 475778, tail = 475778, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[2]->in_ring > $12 = {r = {name = "dsw0_p2", '\000' , flags = 6, memzone = 0xc0000001b0, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 313358, > tail = 313358, single = 0}, pad1 = 0 '\000', cons = {head = 313358, tail = 313358, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[3]->in_ring > $13 = {r = {name = "dsw0_p3", '\000' , flags = 6, memzone = 0xc000000240, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 165403, > tail = 165403, single = 0}, pad1 = 0 '\000', cons = {head = 165403, tail = 165403, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[4]->in_ring > $14 = {r = {name = "dsw0_p4", '\000' , flags = 6, memzone = 0xc0000002d0, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 208237, > tail = 208237, single = 0}, pad1 = 0 '\000', cons = {head = 208237, tail = 208237, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[5]->in_ring > $15 = {r = {name = "dsw0_p5", '\000' , flags = 6, memzone = 0xc000000360, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 633700, > tail = 633700, single = 0}, pad1 = 0 '\000', cons = {head = 633700, tail = 633700, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[6]->in_ring > $16 = {r = {name = "dsw0_p6", '\000' , flags = 6, memzone = 0xc0000003f0, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 152617, > tail = 152617, single = 0}, pad1 = 0 '\000', cons = {head = 152617, tail = 152617, single = 1}, pad2 = 0 '\000'}} > (gdb) p *((struct dsw_evdev *)rte_eventdevs[0].data->dev_private)->ports[7]->in_ring > $17 = {r = {name = "dsw0_p7", '\000' , flags = 6, memzone = 0xc000000480, size = 32768, mask = 32767, capacity = 16384, pad0 = 0 '\000', prod = {head = 0, tail = 0, > single = 0}, pad1 = 0 '\000', cons = {head = 0, tail = 0, single = 1}, pad2 = 0 '\000'}} > >