From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-1.0 required=3.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,SPF_PASS,URIBL_BLOCKED autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 1E8FBC43381 for ; Fri, 8 Mar 2019 21:41:43 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id CE6F320684 for ; Fri, 8 Mar 2019 21:41:42 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="bcOCOwF0" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726338AbfCHVll (ORCPT ); Fri, 8 Mar 2019 16:41:41 -0500 Received: from mail-wm1-f67.google.com ([209.85.128.67]:51825 "EHLO mail-wm1-f67.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726268AbfCHVlk (ORCPT ); Fri, 8 Mar 2019 16:41:40 -0500 Received: by mail-wm1-f67.google.com with SMTP id n19so13792877wmi.1 for ; Fri, 08 Mar 2019 13:41:38 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=f48tgw1n/Nav6vYPvOM1fNdNSxeplvJcHHhzDJXXT2g=; b=bcOCOwF0XpHpLlm1Oy4l+92WwbW+MrqxxoCG/WjWoMD9uuAxcffIjbb421zP6QYnx7 ADb0+kMaJqO94CFtWp+lvSrkWuIlb9fTY4i55qknA7R2OWBBE7oQPFf6Qp9npWu+yGfZ 1I7TcUfQ60XFCamV0WQdXXWNHoBCdpJ2QEZscOKNvSW6LxTYjgDr6Wg8MurfeStxScbX hQb+MmPrvy/if2CgofEHyDmJuJjkmiLbsv+/7dOOl/+GpHuHYU0k0cQJLqOIbLue2t0B sPZDXpjNmD78J80q8TlqWt2/A0kYBRrJmeHdyl6TKX7R41rvEpyf5kly8dxR1Q2S+Ln0 2p3g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=f48tgw1n/Nav6vYPvOM1fNdNSxeplvJcHHhzDJXXT2g=; b=D6Ad3IZogric2ss+aP8jWsoY5DKSXywb+lsoX4Ka8Cr0v6RBeAn9Wgb9vFN52IFWLl UfRQu8s/dlAr/jtiByWxotKE26KQ9QKIy7PKNzhWrCdU4QRt/0JMGTRGutmaQi9pOWE+ CQXi6oDAenGabTXKKPJyF9b6oxFienJI2VgmwPDaX0diYNe99I5Kz5bNka7IuTGgxv5w 2UxrZO4a6W004jO1VZw2yU9RSgGB1fZqDmXqe40nEEKKB25z74nTcHff2HLXPX1uUb1p Q7PbL9LRulUQluke0mkVh90IzbMNc2ytI2cDgmmN7bLyibVluXhpB1j2aVmQ0luSylaw bhkw== X-Gm-Message-State: APjAAAXazUY3SimtkHS/FLbbevFHzeFkhCnaBO4TfVkTeZWZ+sOWVULD zaX3KRzSt06wM5rdRsr0xePOfm3pG8CJ7OBvsJI= X-Google-Smtp-Source: APXvYqzYweJYeL8U0QNTIDfxv8faALMJTmms7PUW4H9vbH5/a5mNUtGcFIPO3WpeCGiD6b1I+GEQ1rbtBKiFfZdDBCU= X-Received: by 2002:a1c:df07:: with SMTP id w7mr10533994wmg.23.1552081298028; Fri, 08 Mar 2019 13:41:38 -0800 (PST) MIME-Version: 1.0 References: <20190228185758.6f37i2sfnr2mdrce@localhost> In-Reply-To: From: Paul Thomas Date: Fri, 8 Mar 2019 16:41:26 -0500 Message-ID: Subject: Re: [Linuxptp-devel] strangeness To: Harini Katakam Cc: "linuxptp-devel@lists.sourceforge.net" , netdev@vger.kernel.org Content-Type: text/plain; charset="UTF-8" Sender: netdev-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: netdev@vger.kernel.org On Fri, Mar 8, 2019 at 1:07 PM Paul Thomas wrote: > > Hi Harini, > > On Fri, Mar 8, 2019 at 1:08 AM Harini Katakam wrote: > > > > Hi Paul, > > On Fri, Mar 8, 2019 at 12:33 AM Paul Thomas wrote: > > > > > > On Thu, Mar 7, 2019 at 12:32 AM Harini Katakam wrote: > > > > > > > > Hi Paul, > > > > On Thu, Mar 7, 2019 at 4:38 AM Paul Thomas wrote: > > > > > > > > > > On Fri, Mar 1, 2019 at 1:24 AM Harini Katakam wrote: > > > > > > > > > > > > +netdev > > > > > > > > > > > > Hi Paul, > > > > > > On Fri, Mar 1, 2019 at 12:29 AM Richard Cochran > > > > > > wrote: > > > > > > > > > > > > > > On Thu, Feb 28, 2019 at 12:33:26PM -0500, Paul Thomas wrote: > > > > > > > > Yes changing it to TSTAMP_ALL_PTP_FRAMES instead of TSTAMP_ALL_FRAMES > > > > > > > > does seem to fix the ssh issue. My worry is that there is still a bug > > > > > > > > somewhere in the network stack that this is just masking. > > > > > > > > > > > > Ok thanks. > > > > > > One place to check in the driver will be: > > > > > > if (gem_ptp_do_txstamp(queue, skb, desc) == 0) { > > > > > > /* skb now belongs to timestamp buffer > > > > > > * and will be removed later > > > > > > */ > > > > > > tx_skb->skb = NULL; > > > > > > } > > > > > > When all TX packets are timestamped, the skb always belongs to the > > > > > > timestamp buffer. > > > > > > > > > > > > > > > > > > > > Or the HW isn't sending the frames in the first place. > > > > > > > > > > > > > > Check that first! > > > > > > > > > > > > To check this, the statistics registers in MAC will be one way. > > > > > > But if there is no TX completion interrupt, then I wouldn't expect > > > > > > these statistics to increase either. The used bit status in BD dump > > > > > > might be of more use. > > > > > > > > > > > > I will also try to reproduce (with TX timestamp ALL) and see if any of > > > > > > the above gives some clue. > > > > > > > > > > > > Regards, > > > > > > Harini > > > > > > > > > > Hi Harini, any luck looking at this? > > > > > > > > I'm sorry, I was not able to debug this further. > > > > > > > > > > > > > > I didn't get very far, even in the "broken" state I see plenty of tx_frames: > > > > > root@xu5:/opt/linuxptp# ethtool -S eth0 > > > > > NIC statistics: > > > > > ... > > > > > tx_frames: 39763 > > > > > ... > > > > > > > > > > When you said "registers in the MAC" is ethtool -S displaying that? > > > > > > > > Yes, ethtool does display these statistics. > > > > I was referring to the registers starting offset 0xFF0B0108 (for GEM0) here: > > > > https://www.xilinx.com/html_docs/registers/ug1087/ug1087-zynq-ultrascale-registers.html > > > > If you see this value increasing, then the MAC is transmitting successfully. > > > > Although, I realize it could be other traffic. To see if specific > > > > packets (for the > > > > failed SSH connection) are not being queued, a BD dump might help. > > > > > > > > Regards, > > > > Harini > > > > > > OK, I think things are becoming more clear. After just doing ioctl(fd, > > > SIOCSHWTSTAMP, &ifreq) from userspace (tx_bd_control = > > > TSTAMP_ALL_FRAMES in macb_ptp.c) then with the nc experiment some udp > > > transmits do not make it to macb_start_xmit() until receive traffic on > > > the nc connection comes in (one-to-one, one new rx packet means one > > > old tx packet goes out). > > > > Could you please share any wireshark log or dump for what is being > > received here? > > Here are two wireshark captures, the thing to note in the bad one is > that packets No. 5, 7, 9 from .102 to .103 were actually sent just > after packet No. 2 but they don't show up on the wire until the > packets the other way (one for one). > > > > > > > > > Working setup: > > > Before the tx_bd_control = TSTAMP_ALL_FRAMES. > > > Every time I hit "sN Enter" from nc I see a macb_start_xmit > > > print_hex_dump() and I see the packet on the nc client side: > > > # nc -l -u -p 9999 > > > ... > > > s11 > > > [ 347.517080] macb_start_xmit data: 00000000: 20 b0 f7 04 0a 29 20 b0 > > > f7 04 0a 26 08 00 45 00 ....) ....&..E. > > > s12 > > > [ 348.964369] macb_start_xmit data: 00000000: 20 b0 f7 04 0a 29 20 b0 > > > f7 04 0a 26 08 00 45 00 ....) ....&..E. > > > ... > > > > > > Broken setup: > > > After the tx_bd_control = TSTAMP_ALL_FRAMES. > > > Not the first nc packet, but many of the subsequent ones never make it > > > to macb_start_xmit() > > > # nc -l -u -p 9999 > > > ... > > > s3 > > > s4 > > > s5 > > > ... > > > Eventually after I send data from the client nc I do see the > > > macb_start_xmit() lines. > > > > Thanks for this debug. If macb_start_xmit is never called, one of > > the preceeding checks (such as if skb is present or if the TX queues > > are off etc) > > should fail. I'm still tracing this but I'm not sure under what > > circumstances only > > some UDP packets will be prevented from being transmitted. > In this specific test the first tx packets always goes through, and > the subsequent ones don't until rx packets. So it's not random when > they go through, I could have been clearer about that. > > > Just to be sure, could you please confirm you are not seeing any > > "buffer exhausted" messaged from TX error tasks? > Correct, I'm not seeing any "buffer exhausted" errors. > > thanks, > Paul And one more piece that may be helpful. I think I narrowed down what's happening in the receive that finally flushes out a pending tx packet. It seems to be the netif_receive_skb(skb); line in gem_rx() (line 1067). I tested with an mdelay before and after this call: mdelay(1000);//mdelay here is slow to flush the pending tx packet (as seen by nc client) netif_receive_skb(skb); //mdelay(1000);//mdelay here is fast to flush the pending tx packet (as seen by nc client) This seems very strange to me, I quickly glanced at what netif_receive_skb() is doing and didn't see anything connected with the TX path, but those are the symptoms. thanks, Paul