Author Topic: Slow Telnet  (Read 10255 times)

Offline hervé

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Slow Telnet
« on: December 01, 2010, 08:20:01 AM »
Hi Mark,

When I test my board, after some hours, the telnet becomes really slow : event the echo takes some secund to be send.
All the debug output are then send by packet but not completely, and later complete.

Do you have an idea where to search for this type of problem ?

Thanks.

Offline mark

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 3234
    • View Profile
    • uTasker
Re: Slow Telnet
« Reply #1 on: December 01, 2010, 10:12:32 AM »
Hi Hervé

I think that you will need to see what is happening by making a Wireshark recording. You can then see which side of the connection is responsible for the delay.

Regards

Mark

Offline hervé

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Slow Telnet
« Reply #2 on: December 01, 2010, 01:08:27 PM »
Hi Mark,

Of course I did but not so easy to analyze.
What looks strange is that the debug send a block of data at once, but the display show only some data then waits 2 or 3secunds then continue.

How is it possible during the same sending routine?

Offline hervé

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Slow Telnet
« Reply #3 on: December 02, 2010, 09:03:34 AM »
Hi Mark,

To illustrate my statements : (4 frames to send one written information)


Offline mark

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 3234
    • View Profile
    • uTasker
Re: Slow Telnet
« Reply #4 on: December 02, 2010, 12:37:07 PM »
Hi Hervé

The TELNET TCP windowing operation is explained in chapter 6 in http://www.utasker.com/docs/uTasker/uTaskerTELNET.PDF
It is possible (and normal) that debug outputs are sent in more that one frame but usually only the first frame will be of small content since the maximum amount of buffered data is sent in each frame.

Could you upload the Wireshark recoring since I can then also look in more detail at the frames - at the moment I don't see anything anormal based on TCP content, but I think the issue is more about the timing.

I would only expect delays when there are lost TCP transmissions or receptions an dthus repeats take place. I don't see any reception loss and also I don't think that there is any transmssion loss (a repetition when sending will generally result in large TCP frames being send becasue there is mnore waiting data in the meantime and this doesn't seem to be true). I note that windowing operation is taking place and also a final frame has a lot more content (all expected operation).

Regards

Mark

PS: Did you make the change from this post?
http://www.utasker.com/forum/index.php?topic=1001.0

I have generally deactivated thsi since I was sometimes getting strange behavior (slow web pages). I think that it is because an Ethernet reception event was being lost (internal queue overflow - increasing Ethernet task queue would possibly solve it) and it caused the Ethernet reception to be always one frame behind (loss of synchronisation). I don't however think that it is your problem but best to at least mention it just in case...

Offline hervé

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Slow Telnet
« Reply #5 on: December 02, 2010, 02:06:56 PM »
Hi Mark,

In case you got some idea I send you a part of the wireshark's record. Use filter :ip.addr == 192.168.30.26
(The referred change has been made)

http://tech.voila.net/badge_lent_1001.pcap
« Last Edit: December 02, 2010, 02:11:45 PM by hervé »

Offline mark

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 3234
    • View Profile
    • uTasker
Re: Slow Telnet
« Reply #6 on: December 03, 2010, 02:22:31 PM »
Hi Hervé

1) Try disabling the change in the other link to be sure.

2) Looking in more detail at the wireshark recording I still get the feeling that the application is causing pauses and not the TCP (TELNET) interface layer.
The reason for this is the content pattern which looks to match the expected behavior.

Here is a short introduction as to what is expected.

Assume the following code sending debug messages to a connected TELNET interface:

fnDebugMsg("Test ");
fnDebugMsg("1");
fnDebugMsg("2");
fnDebugMsg("3");
fnDebugMsg("\r\n");


I would expect this to be sent as three TCP frames. The first frame carrying the data "Test ", the second carrying "1" and the third "23\r\n". This can be explained as follows.
- The first call puts the data "Test " to the TCP buffer and the buffer content is immediately sent by the TCP layer. Since it doesn't have any further buffer data a small TCP frame is sent.
-The second call adds "1" to the TCP buffer and this extra content is also immediately sent by the TCP layer (the TCP layer will initially allow 2 frames to be sent without waiting for an ACK).
- The third call adds "2" to the buffer but no TCP frame is sent because there have not yet been ACKS received to the previous TCP transmissions - thsi data waits in the buffer.
- The following calls also add the data to the TCP buffer but will also not cause any data to be sent.

When an ACK is received back from the TELNET client (either acknowledging just the first packet but more likely acknowledging both packets at the same time) the TELNET server will send following buffer content. It will send as much as possible and so the 'rest' of the waiting data is sent in a single TCP frame.

Now assume that the first frames could not be sent (or get lost, or the ACK is lost). This means that there will be a TCP timeout and the buffer data (all outstanding data) will be repeated. In this case the repeat will consist of just one single TCP frame containing the content "Test 123\r\n". Repeated data will send as much waiting buffer data as possible and not just the content of individual frames that were lost.

In the recording I see that some data is sent after a delay of 1..2 seconds but the data is still being sent as several short frames followed (when there is more data) by a longer frame. This is in keeping the expected content behavior when the application sends this after a delay and not when the TCP layer is delayed due to TCP protocol errors.


- It would be intersting to see a recording when the delays don't take place.
- Could you also check whether there is a possibility of the application being delayed between each call in a sequence.


What I am not absolutely sure about is whether you are using a TELNET socket or a buffered TCP socket on the TELNET port. ALso whether the debug messages are being sent as a sequence (as in the example above) or are being build up in smaller chunks after receiving acknowledgements. I have tried analysing just one occurrence in the recording with a delay:
- frame 31.  I assume that the code is performing one output calls with the content " \r\n\r\n pupitre : badge=00275516 pupitre : etat=0\r\n"
- frame 32. The TELNET client acknowledges thsi but there is no further reaction
- frame 91. The code is now sending "M_Badge -> Status = MS_VALID"

Frame 91 is delayed by around 2 seconds.

However, assuming that the application actually called 2 calls immediately after another with the two contents it would mean that the second transmission never took place (or got lost). Frame 32 is then a 'normal' TCP repetition.

However this doesn't explain why the next frame 144 is sent after another 1s delay. In this case there are 2 immediate frame transmissions with content "Jeudi" and "02". This would suggest a 'normal' sequence of 2 calls as opposed to waiting data in the TCP buffer.

If I then also look at the other network data (after removing the filter) I don't see any frames that would otherwise cause any impact (eg. no broadcasts which would cause the Ethernet task to be activated and subsequently 'kick-on' any data due to a queue-stall etc.).


Regards

Mark


Offline hervé

  • Jr. Member
  • **
  • Posts: 98
    • View Profile
Re: Slow Telnet
« Reply #7 on: December 06, 2010, 12:52:50 PM »
Hi Mark,

I made a record where the telnet output looks normal : in fact the frames are also cut in differents small parts.

My problem is not coming from this cutout...
http://tech.voila.net/normal.pcap

pupitre : badge=00275516  pupitre : etat=0
M_Badge -> Status = MS_VALID

Mardi 07/12/10  07:41:44    Rapport de debug :

tabDebug[0]:    ID=W(57)        cptError=0      dureeMax=1
tabDebug[1]:    ID=A(41)        cptError=0      dureeMax=1
tabDebug[2]:    ID=E(45)        cptError=0      dureeMax=13
tabDebug[3]:    ID=T(54)        cptError=0      dureeMax=3
tabDebug[4]:    ID=a(61)        cptError=0      dureeMax=1
tabDebug[5]:    ID=m(6d)        cptError=0      dureeMax=1
tabDebug[6]:    ID=d(64)        cptError=0      dureeMax=1
tabDebug[7]:    ID=S(53)        cptError=0      dureeMax=1
tabDebug[8]:    ID=p(70)        cptError=0      dureeMax=1
tabDebug[9]:    ID=G(47)        cptError=0      dureeMax=1
tabDebug[10]:   ID=y(79)        cptError=0      dureeMax=1
tabDebug[11]:   ID=e(65)        cptError=0      dureeMax=1
tabDebug[12]:   ID=r(72)        cptError=0      dureeMax=1
tabDebug[13]:   ID=v(76)        cptError=0      dureeMax=97
tabDebug[14]:   ID=f(66)        cptError=0      dureeMax=1
tabDebug[15]:   ID=b(62)        cptError=0      dureeMax=50
tabDebug[16]:   ID=x(78)        cptError=0      dureeMax=3
tabDebug[17]:   ID=R(52)        cptError=0      dureeMax=9
tabDebug[18]:   ID=C(43)        cptError=0      dureeMax=1

tabSequence[C, W, A, E, T, a, m, d, S, p, G, y, e, r, v, f, b, x, R, C, W, A, E, T, a, m, d, S, p, G, y, e, r, v, f, b, x, R, C, W, A, E, T, a, m, d, S, p, G, y, e, r, v, f, b, x, R, C, W, A, E, T, a, m, d, S, p, G, y, e, r, v, f, b, x, R, C, W, A, E, T, a, m, d, S, p, G, y, e, r, v, f, b, x, R, C, W, A, E, T, a, m, d, S, p, G, y, e, r, v, f, b, x, R, C, W, A, E, T, a, m, d, S, p, G, y, e, r, ]
cptErrorMalloc=0


pupitre : badge=00275516  pupitre : etat=0

For example the date is displayed through a call to a function
Code: [Select]
void showDate(void)
{
    switch(stPresentTime.ucDayOfWeek)
    {
        case 1 : fnDebugMsg("Dimanche "); break;
        case 2 : fnDebugMsg("Lundi "); break;
        case 3 : fnDebugMsg("Mardi "); break;
        case 4 : fnDebugMsg("Mercredi "); break;
        case 5 : fnDebugMsg("Jeudi "); break;
        case 6 : fnDebugMsg("Vendredi "); break;
        case 7 : fnDebugMsg("Samedi "); break;
    }

    fnDebugDec(stPresentTime.ucDayOfMonth,2);
    fnDebugMsg("/");
    fnDebugDec(stPresentTime.ucMonth,2);
    fnDebugMsg("/");
    fnDebugDec(stPresentTime.ucYear,2);
    fnDebugMsg("  ");
}
Between each call to a fnDebug function the buffer is sent ?

« Last Edit: December 07, 2010, 07:49:22 AM by hervé »

Offline mark

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 3234
    • View Profile
    • uTasker
Re: Slow Telnet
« Reply #8 on: December 09, 2010, 05:36:16 PM »
Hi Hervé

I still can't explain anything. For your code sequence I expect the following:

    fnDebugMsg("Samedi ");                                 -> TCP Frame with Samedi
    fnDebugDec(stPresentTime.ucDayOfMonth,2);   -> TCP Frame with value of stPresentTime.ucDayOfMonth
    fnDebugMsg("/");                                          -> / put to buffer
    fnDebugDec(stPresentTime.ucMonth,2);           -> "stPresentTime.ucMonth" put to buffer
    fnDebugMsg("/");                                           -> / put to buffer
    fnDebugDec(stPresentTime.ucYear,2);              -> "stPresentTime.ucYear" put to buffer
    fnDebugMsg("  ");                                         -> "  " put to buffer
                                                   on ACK to the first TCP frames (after a few ms - but certainly longer than the code takes) a single frame is expected containing the buffer content.

Since the code above will not be interrupted by TCP reception I can't explain any other pattern.

Regards

Mark