Menu

Port to vxWorks

Help
ckohrt
2006-11-11
2012-11-23
  • ckohrt

    ckohrt - 2006-11-11

    I recently started to port PTPd to vxWorks and so far I can compile the source and download it to the Motorola mbx860 target. Now, I can run the software and the following messages are shown. I can not understand what the problem is. May be you could assist me to find the problem, please.

    Here the messages:

    ------------ Init: It seems that everything works well here ------------
    mainallocated 600 bytes for foreign master data
    protocolevent POWERUP
    toState
    state PTP_INITIALIZING
    stopping timer
    timer stopped
    manufacturerIdentity: Kendall;1b3
    shutdown net
    UID: 08:00:3E:27:E6:D9
    open sockets
    ifName = 192.168.2.20
    find a network interface
    allow address reuse
    bind sockets
    set general and port address
    set subdomain address
    mRouteAdd to 224.0.1.129 and 192.168.2.20.
    multicast send only on specified interface
    set socket time to life to 1
    init other stuff
    init data
    initData
    init timer
    init clock
    initClock
    sync message interval: 2
    clock identifier: DFLT
    256*log2(clock variance): -4000
    clock stratum: 4
    clock preferred?: no
    bound interface name: 192.168.2.20
    communication technology: 0
    uuid: 08:00:3e:27:e6:d9
    PTP subdomain name: _DFLT
    subdomain address: e0.0.1.81
    event port address: 1 3f
    general port address: 1 40

    ------------ Now the protocol state machine ------------
    Are those messages OK? Because I have attached a second computer and shouldn't they start to communicate immediately?
    --------------------------------------------------------

    toState
    state PTP_LISTENING
    timerStart: set timer 0 to 20
    activity
    doState
    handle
    catch_alarm: elapsed 0 250000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 500000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 750000000
    no activity
    doState
    handle
    catch_alarm: elapsed 1 0
    no activity
    doState
    handle
    catch_alarm: elapsed 0 250000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 500000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 750000000
    no activity
    doState
    handle
    catch_alarm: elapsed 1 0

    ------------ Announce MASTER ------------
    After lots of messages (approx. 30-50) with no activity, here the Master is announced and the sync timer is set to 2 seconds.
    Is this right so far?
    --------------------------------------------------------

    doState
    handle
    catch_alarm: elapsed 1 0
    no activity
    doState
    handle
    catch_alarm: elapsed 0 250000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 500000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 750000000
    no activity
    doState
    handle
    catch_alarm: elapsed 1 0
    timerUpdate: timer 0 expired
    event SYNC_RECEIPT_TIMEOUT_EXPIRES
    toState
    state PTP_MASTER
    timerStart: set timer 1 to 2
    activity
    doState
    handle
    catch_alarm: elapsed 0 250000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 500000000
    no activity
    doState
    handle
    catch_alarm: elapsed 0 750000000
    no activity

    ------------ First SYNC Message ------------
    Now timer 1 expires after 2 sec. and I get in this example 2 messages back... but from myself. I can imagine that this is OK, but there must be a message from the other computer. Isn't it?
    --------------------------------------------------------

    doState
    timerUpdate: timer 1 expired
    event SYNC_INTERVAL_TIMEOUT_EXPIRES
    issueSyncuser-space send time stamp 23s 716666638ns
    event Send 0 Message at 23s 716666638ns
    event Send 2 Message
    handle
    kernel recv time stamp 23s 716666638ns
    msgUnpackHeader: versionPTP 1
    msgUnpackHeader: versionNetwork 1
    msgUnpackHeader: subdomain _DFLT
    msgUnpackHeader: messageType 1
    msgUnpackHeader: sourceCommunicationTechnology 0
    msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
    msgUnpackHeader: sourcePortId 1
    msgUnpackHeader: sequenceId 1
    msgUnpackHeader: control 0
    event Receipt of Message
       type 0
       uuid 08:00:3e:27:e6:d9
       sequence 1
       time 23s 716666638ns
    handleMessage: ignoring message from self
    activity
    doState
    handle
    msgUnpackHeader: versionPTP 1
    msgUnpackHeader: versionNetwork 1
    msgUnpackHeader: subdomain _DFLT
    msgUnpackHeader: messageType 2
    msgUnpackHeader: sourceCommunicationTechnology 0
    msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
    msgUnpackHeader: sourcePortId 1
    msgUnpackHeader: sequenceId 1catch_alarm: elapsed 0 250000000

    msgUnpackHeader: control 2
    event Receipt of Message
       type 2
       uuid 08:00:3e:27:e6:d9
       sequence 1
       time 0s 0ns
    handleMessage: ignoring message from self
    activity
    doState
    handle
    catch_alarm: elapsed 0 500000000
    no activity
    doState
    handle
    no activity
    doState
    handle
    catch_alarm: elapsed 0 750000000
    no activity

    ------------ Probably mistake here somewhere ------------
    I got completely lost on the next messages. But there are lots of zeros. Is that correct? What's happening here? Why is followup message "unwanted"?
    --------------------------------------------------------

    no activity
    doState
    handle
    catch_alarm: elapsed 1 0
    no activity
    doState
    timerUpdate: timer 1 expired
    event SYNC_INTERVAL_TIMEOUT_EXPIRES
    issueSyncuser-space send time stamp 25s 849999966ns
    event Send 0 Message at 25s 849999966ns
    event Send 2 Message
    handle
    kernel recv time stamp 25s 849999966ns
    msgUnpackHeader: versionPTP 1
    msgUnpackHeader: versionNetwork 1
    msgUnpackHeader: subdomain _DFLT
    msgUnpackHeader: messageType 1
    msgUnpackHeader: sourceCommunicationTechnology 0
    msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
    msgUnpackHeader: sourcePortId 2
    msgUnpackHeader: sequenceId 1
    msgUnpackHeader: control 0
    event Receipt of Message
       type 0
       uuid 08:00:3e:27:e6:d9
       sequence 1
       time 25s 849999966ns
    addForeignupdateForeign
    updateForeign: new record (0,1) 0 2 08:00:3e:27:e6:d9
    msgUnpackHeader: versionPTP 1
    msgUnpackHeader: versionNetwork 1
    msgUnpackHeader: subdomain _DFLT
    msgUnpackHeader: messageType 1
    msgUnpackHeader: sourceCommunicationTechnology 0
    msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
    msgUnpackHeader: sourcePortId 2
    msgUnpackHeader: sequenceId 1
    msgUnpackHeader: control 0
    msgUnpackSync: originTimestamp.seconds 25
    msgUnpackSync: originTimestamp.nanoseconds 849999966
    msgUnpackSync: epochNumber 0
    msgUnpackSync: currentUTCOffset 0
    msgUnpackSync: grandmasterCommunicationTechnology catch_alarm: elapsed 0 250000000
    0
    msgUnpackSync: grandmasterClockUuid 08:00:3e:27:e6:d9
    msgUnpackSync: grandmasterPortId 2
    msgUnpackSync: grandmasterSequenceId 0
    msgUnpackSync: grandmasterClockStratum 0
    msgUnpackSync: grandmasterClockIdentifier DFLT
    msgUnpackSync: grandmasterClockVariance 0
    msgUnpackSync: grandmasterPreferred 0
    msgUnpackSync: grandmasterIsBoundaryClock 0
    msgUnpackSync: syncInterval 0
    msgUnpackSync: localClockVariance 0
    msgUnpackSync: localStepsRemoved 0
    msgUnpackSync: localClockStratum 0
    msgUnpackSync: localClockIdentifer DFLT
    msgUnpackSync: parentCommunicationTechnology 0
    msgUnpackSync: parentUuid 08:00:3e:27:e6:d9
    msgUnpackSync: parentPortField 0
    msgUnpackSync: estimatedMasterVariance 0
    msgUnpackSync: estimatedMasterDrift 0
    msgUnpackSync: utcReasonable 0
    handleSync
    SYNC_RECEIPT_TIMER reset
    timerStart: set timer 0 to 20
    activity
    doState
    bmc: best record 0
    bmcDataSetComparison: start
    toState
    timerStart: set timer 0 to 20
    state PTP_PTP_SLAVE
    initClock
    Q = 0, R = 5
    handle
    activity
    doState
    handle
    msgUnpackHeader: versionPTP 1
    msgUnpackHeader: versionNetwork 1
    msgUnpackHeader: subdomain _DFLT
    msgUnpackHeader: messageType 2
    msgUnpackHeader: sourceCommunicationTechnology 0
    msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
    msgUnpackHeader: sourcePortId 2
    msgUnpackHeader: sequenceId 1
    msgUnpackHeader: control 2
    event Receipt of Message
       type 2
       uuid 08:00:3e:27:e6:d9
       sequence 1
       time 0s 0ns
    msgUnpackFollowUp: associatedSequenceId 0
    msgUnpackFollowUp: preciseOriginTimestamp.seconds 25
    msgUnpackFollowUp: preciseOriginTimestamp.nanoseconds 849999966
    handleFollowUphandleFollowUp: looking for uuid 08:00:3e:27:e6:d9
    handleFollowUp: unwanted
    activity
    doState
    handle
    catch_alarm: elapsed 0 500000000
    no activity
    doState
    handle
    no activity
    doState
    handle
    catch_alarm: elapsed 0 750000000
    no activity
    doState
    handle
    catch_alarm: elapsed 1 0
    no activity
    doState
    handle
    catch_alarm: elapsed 0 250000000
    no activity

    --------------------------------------------------------
    THANK YOU VERY MUCH!!!

    Christian K.
    --------------------------------------------------------

     
    • kendall

      kendall - 2006-11-15

      You should usually only use the normal (PTPD_DBG) level because the verbose (PTPD_DBGV) is usually way too much information. Everything above looks ok though. Here's the normal sequence for PTPd's startup:

      init everything
      wait 20s for a sync message
      if sync message received, then become a slave and listen for syncs
      else if timeout, then become a master and send a sync message every 2s

      All of the the things you metioned are ok. Initially, PTPd starts up in the listening state and waits for a sync message until a timeout. I think this is required by the spec. This means that if there are no other PTP node active on the network, there will be an period of inactivity until one node times out and starts sending messages.

      Receiving messages from yourself is ok, and is in fact necessary in the latest builds of PTPd in from Subversion.

      Followup messages are unwanted if they don't match a prior sync message. The first followup message after transitioning to the slave state matches the sync message that caused the trnasition to the slave state; however, PTPd thinks its unwanted because it doesn't keep track of the sync message info across the state transistion. No big deal because it'll just start again with the next sync message.

      Finally, all of the zeros in the output look ok.

      As a fisrt level of debugging, make sure messages are going out on the wire ok. You can sniff the traffic with ethereal (now wireshark). You should see regualr sync/followps from the master, and infrequent delay requests from the slave.

      Next, with the PTPD_DBG compile flag on the slave, you should see clock servo updates for every sync message. If you see this, then everything is working all the way down the stack. If you see the offset getting pushed to zero, you know that the frequency adjustment is working too.

       
    • ckohrt

      ckohrt - 2006-11-17

      Hi kendall!

      Thank you very much for your answer. I followed your suggestions and could verify with etherreal, that the master sends the sync message and the follow up message every 2 seconds. I also reduced the number of debug outputs, so it is a bit better to read.

      It seems to me, that there is no communication between the master and slave. The reason for that is maybe the check if the followup message is valid, especially the sequence id. On my system the latter is never increased and is always shown as "0".
      Is it OK that this variable stays at zero?

      Thanx again!
      darkuniverse

      ---------
      issueSync
      ptpClock->parent_last_sync_sequence_number: 1
      ---------user-space send time stamp 303s 183333326ns
      kernel recv time stamp 303s 183333326ns
      ptpd: msgUnpackHeader: versionPTP 1
      msgUnpackHeader: versionNetwork 1
      msgUnpackHeader: subdomain _DFLT
      msgUnpackHeader: messageType 1
      msgUnpackHeader: sourceCommunicationTechnology 0
      msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
      msgUnpackHeader: sourcePortId 0
      msgUnpackHeader: sequenceId 1
      msgUnpackHeader: control 0
      ptpd: msgUnpackHeader: versionPTP 1
      msgUnpackHeader: versionNetwork 1
      msgUnpackHeader: subdomain _DFLT
      msgUnpackHeader: messageType 1
      msgUnpackHeader: sourceCommunicationTechnology 0
      msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
      msgUnpackHeader: sourcePortId 0
      msgUnpackHeader: sequenceId 1
      msgUnpackHeader: control 0
      -------------- method msgUnpackSync -----------
      msgUnpackSync: originTimestamp.seconds 303
      msgUnpackSync: originTimestamp.nanoseconds 183333326
      msgUnpackSync: epochNumber 0
      msgUnpackSync: currentUTCOffset 0
      msgUnpackSync: grandmasterCommunicationTechnology 0
      msgUnpackSync: grandmasterClockUuid 08:00:3e:27:e6:d9
      msgUnpackSync: grandmasterPortId 0
      msgUnpackSync: grandmasterSequenceId 0
      msgUnpackSync: grandmasterClockStratum 0
      msgUnpackSync: grandmasterClockIdentifier DFLT
      msgUnpackSync: grandmasterClockVariance 0
      msgUnpackSync: grandmasterPreferred 0
      msgUnpackSync: grandmasterIsBoundaryClock 1
      msgUnpackSync: syncInterval 0
      msgUnpackSync: localClockVariance 0
      msgUnpackSync: localStepsRemoved 0
      msgUnpackSync: localClockStratum 0
      msgUnpackSync: localClockIdentifer DFLT
      msgUnpackSync: parentCommunicationTechnology 0
      msgUnpackSync: parentUuid 08:00:3e:27:e6:d9
      msgUnpackSync: parentPortField 0
      msgUnpackSync: estimatedMasterVariance 0
      msgUnpackSync: estimatedMasterDrift 0
      msgUnpackSync: utcReasonable 0
      timerStart: set timer 0 to 20
      ptpd: msgUnpackHeader: versionPTP 1
      msgUnpackHeader: versionNetwork 1
      msgUnpackHeader: subdomain _DFLT
      msgUnpackHeader: messageType 2
      msgUnpackHeader: sourceCommunicationTechnology 0
      msgUnpackHeader: sourceUuid 08:00:3e:27:e6:d9
      msgUnpackHeader: sourcePortId 132
      msgUnpackHeader: sequenceId 1
      msgUnpackHeader: control 2
      msgUnpackFollowUp: associatedSequenceId 0
      msgUnpackFollowUp: preciseOriginTimestamp.seconds 303
      msgUnpackFollowUp: preciseOriginTimestamp.nanoseconds 183333326

       
    • ckohrt

      ckohrt - 2006-11-18

      I just found out that in those lines in msg.c the packfollowup and unpackfollowup methods maybe do not fit together:

      void msgPackFollowUp(void *buf, UInteger16 associatedSequenceId,
        TimeRepresentation *preciseOriginTimestamp, PtpClock *ptpClock)
      {
      ...
        *(Integer32*)(buf + 40) = shift16(flip16(associatedSequenceId), 1);
        *(Integer32*)(buf + 44) = flip32(preciseOriginTimestamp->seconds);
      ...
      }
      -->4 Bytes between 40 and 44. See the unpack method:

      void msgUnpackFollowUp(void *buf, MsgFollowUp *follow)
      {
        follow->associatedSequenceId = flip16(*(UInteger16*)(buf + 42));
        ...
        follow->preciseOriginTimestamp.seconds = flip32(*(UInteger32*)(buf + 44));
      ...
      }
      --> Here from 42 to 44 = 2 Bytes
      Maybe I do not understand the code.

      When I change to the following, everything works:

      void msgUnpackFollowUp(void *buf, MsgFollowUp *follow)
      {
      follow->associatedSequenceId = flip32(*(UInteger32*)(buf + 40));
      ...
      }

      void msgUnpackFollowUp(void *buf, MsgFollowUp *follow)
      {
        follow->associatedSequenceId = flip32(*(UInteger32*)(buf + 40));
      ... 
      }

      void msgPackFollowUp(void *buf, UInteger16 associatedSequenceId,
        TimeRepresentation *preciseOriginTimestamp, PtpClock *ptpClock)
      {
      ...
         *(Integer32*)(buf + 40) = flip32(associatedSequenceId);
      ...
      }

      Could anybody who knows about msg.c have a look at it?

      Thanx

       
    • kendall

      kendall - 2006-11-18

      I'm not sure what's breaking, the message pack or unpack. The msgPack...() code is not so intuitive, sorry. The idea is to pack a word at a time. Sub-wordlength values should get shifted into the proper location in the word and OR'ed together. Ethereal displays its decoding of PTP messages in the middle pane, so you can use it to check if the sent message is getting packed properly. If the associatedSequenceId is not getting shifted into the right location, you can check the hexdump in ethereal's bottom pane to try to find where the associatedSequenceId is ending up.

      If the shift is breaking, it sounds like an architecture issue. I've only tried the code on x86, m68k, and ppc. Others have tried it on blackfin, and there was a small fix to PTPd needed there. What architecture are you running?

       
      • ckohrt

        ckohrt - 2006-11-19

        Hi kendall,

        I am using the Motorola PowerPC (PPC) MPC860 Board and vxWorks. Your help is quite good! I will figure out whether the pack/unpack works. It's good to know why the shift is neccessary. I think I can get it working.

        By the way, I am thinking of checking my modifications into your repository. That would mean, that I would have to add some #defines and #ifs to match the correct target system. Maybe it makes the code too complicated. But I also think we could modify the code so that it is target dependend in a well readable manner. But, before I could do this we should discuss it, if you want and if the code modifications are desired to support target specific environments.

        Best wishes,
        darkuniverse

        PS
        The existing code is already quite readable and well structured.

         
    • ckohrt

      ckohrt - 2006-11-20

      Hi!

      I could figure out what the problem was. Actually, your question about the architecture and the fact that something with the shift operation is wrong leaded to the simple fact, that in my arch. I use BIG ENDIAN and in a header borrowed from cygwin (endian.h) there was little endian defined.

      Then, I changed back my modifications for debugging and: VOILÀ, it is working!

      But still some things are maybe not correct. The output of my code in debug mode is:

      (debug) offset from master:               0s  -400000024ns
      (debug) observed drift:    -512000
      kernel recv time stamp 755s 49999958ns
      timerStart: set timer 0 to 20
      (debug) offset from master:               0s  -400000024ns
      (debug) observed drift:    -512000
      kernel recv time stamp 757s 183333286ns
      timerStart: set timer 0 to 20
      (debug) offset from master:               0s  -400000024ns
      (debug) observed drift:    -512000
      kernel recv time stamp 759s 316666614ns
      timerStart: set timer 0 to 20
      (debug) offset from master:               0s  -400000024ns
      (debug) observed drift:    -512000
      kernel recv time stamp 761s 449999982ns
      timerStart: set timer 0 to 20
      (debug) offset from master:               0s  -400000004ns
      (debug) observed drift:    -512000

      My question is: Why is there always an offset?
      I will check, if the frequency adjustment thing works.... today. Maybe you have got an idea...

      Thanx,
      darkuniverse

       
    • kendall

      kendall - 2006-11-25

      The frequency adjustment does not appear to be working correctly. The value of -512000 for the observed drift means the clock servo is railed. The offset should be changing very quickly in that case. Does vxworks have an adjtimex() or ntp_adjtime() system call?

       
      • ckohrt

        ckohrt - 2006-11-25

        I am currently implementing a new "virtual clock" for the vxWorks. The system clock is only 32 bit which is to less for sync in 1us. I hope that I can implement a clock based on the Timebase register which has 64 bit and add the adjustment things to it. I wil try to use the normal clock with sysClkRateSet() later. The normal clock has a resolution of about 16ms....

        Thank,
        darkuniverse

         

Log in to post a comment.