Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[kitz]

Noticed something strange between DSL stats and HG612modem stats and not sure if one of them is false reporting.

Ive just noticed that the DLM caused me to resync this morning, but what is strange is that in HG612 modem stats it shows me as having a massive burst of CRC errors. Yet theres nothing on DSLstats.  Ive tried turning clipping off but that doesnt show anything either. 

Both show a burst of Err Secs at that time - 15 on DSLstats and 3 on HG612 stats.   Theres certainly a large difference between the two when it comes to CRCs


Is this a reporting error on one of them? - Sorry not sure which is right, but looking at my line stats, could it be that upon resync HG612modem stats has somehow taken the last day figures rather than current?

Code: [Select]

Total time = 1 days 19 hours 27 min 5 sec
FEC:            0               19491820
CRC:            30420           63131
ES:             679             2788
SES:            53              1
UAS:            175             175
LOS:            5               0
LOF:            36              0
LOM:            0               0
Latest 15 minutes time = 12 min 5 sec
FEC:            0               0
CRC:            0               0
ES:             0               0
SES:            0               0
UAS:            0               0
LOS:            0               0
LOF:            0               0
LOM:            0               0
Previous 15 minutes time = 15 min 0 sec
FEC:            0               0
CRC:            0               0
ES:             0               0
SES:            0               0
UAS:            0               0
LOS:            0               0
LOF:            0               0
LOM:            0               0
Latest 1 day time = 19 hours 27 min 5 sec
FEC:            0               16
CRC:            5612            0
ES:             56              0
SES:            10              0
UAS:            28              28
LOS:            1               0
LOF:            7               0
LOM:            0               0
Previous 1 day time = 24 hours 0 sec
FEC:            0               109
CRC:            6609            0
ES:             103             0
SES:            12              0
UAS:            28              28
LOS:            1               0
LOF:            7               0
LOM:            0               0
Since Link time = 6 hours 45 min 53 sec
FEC:            0               7
CRC:            13              0
ES:             11              0
SES:            0               0
UAS:            0               0
LOS:            0               0
LOF:            0               0
LOM:            0               0
 >  

I notice that HG612modem stats gave a similar CRC burst yesterday after a DLM resync that didnt show up in DSLstats either.

[krypton]

Afaik DSLstats uses the OHFErr counter to display crc errors, which is set to zero after a resync.

[les-70]

  I wonder if, when either program detects a resync, that sample is discarded apart from noting the resync.  It may then be luck re what is or is not captured at the resync transition. 

[Bald_Eagle1]

Delta CRC/OHFErr values should be more or less identical, despite their cumulative values being completely different following a resync.

Their cumulative values only match following a modem reboot or a power off/on.

My connection last resynced at 00:45 8th October, but as can be seen from the attached graphs, the CRC & OHFErr delta values are more or less identical.

I'd like to see a modem_stats.log extract that includes the resync period to see if I can work out where that spike came from.

It might just be the way MDWS reports the data or it might have been the burst of errors that actually caused the resync?

[roseway]

The earlier two comments are correct for DSLstats, except that it's a bit more complicated: with each sample I compare the new value of OHFErr (or SFErr for ADSL connections) with the previous, and use this comparison to determine what to feed to the CRC graph. There are several possibilities:

- New value higher than or equal to previous (normal situation)
- New value is zero or very low and previous value was close to the maximum possible (counter wraparound)
- New value is zero or very low and previous value was intermediate (resync or reboot)
- New value has no sensible relationship to the previous (bad data reported by modem)
- This is the first sample (just started recording)

... and more.

I'll have another look at the algorithm to see if I've missed something. The same algorithm is used for all the per-minute values which are derived from total values reported by the modem.

[tbailey2]

Delta CRC/OHFErr values should be more or less identical, despite their cumulative values being completely different following a resync.

If of any help here are some figures from the database around that time. MDWS just reports what it finds in the database for the majority of graphs.

[Bald_Eagle1]

Do you also have the DS CRC cumulative values in the database for the same period?

[tbailey2]

Do you also have the DS CRC cumulative values in the database for the same period?

It appears so although I couldn't see them at first, DS_CRC_Errors2 doesn't have any data but ds_cb1_CRC does contain the matching values to derive the delta values.

[Bald_Eagle1]

So, it seems there were 5559 DS CRC errors & the connection resynced somewhere between the stats being harvested at 09:47 & 09:48


On resyncing, OHFErr counts were reset to zero & cumulative CRC counts continued without being reset.

Assuming the stats following the resync were harvested at say 2 seconds past 09:48, the connection would have been up for 18 - 2 = 16 seconds.

Assuming say 20 seconds for the resync process itself, the resync must have started at around 09:47:24 (36 seconds before 09:47:00)

It would therefore 'appear' that whatever caused the 5559 CRC errors was the cause of the resync.


Once I can see the modem_stats.log data including that resync, I'll be able to decide whether or not to include separate CRC & OHFErr graphs in the FULL__MONTY montage again rather than having a single graph entitled TOTAL DS CRC (OHFerr).

[NewtronStar]

Ive just noticed that the DLM caused me to resync this morning

The DLM is retraining your line after the issues you had with high US errored seconds, it's very normal to have 2 resyncs a day from the DLM it's doing it's best to get your line back to the way is was, have seen that quite a few times when I had line issues   

[kitz]

Delta CRC/OHFErr values should be more or less identical, despite their cumulative values being completely different following a resync.

Ive attached mine for the past 3 days.   They dont appear to show the same data and I cant see any correlation between the spikes on each.

Note that all of the spikes on the DS CRC errors were at a time when the DLM caused resyncs.  The DLM has been applying different settings to my line each and every day now for over a week.  There was an outage at my exchange and when it came back up I was getting thousands of errors per minute and the DLM clamped down soon and quite hard. The fault was fixed on Wednesday, and since then the DLM has been putting things back to normal for me.   This mornings resync was definitely the DLM again.

I'd like to see a modem_stats.log

I'll dig it out and email it you if you like

It might just be the way MDWS reports the data

Dont think its anything to do with MDWS.  The difference is between DSLstats and HG612 modem stats.

might have been the burst of errors that actually caused the resync?

Doubtful as each time of the resync my DLM figure has changed when I resync.

Its happened three days in a row now that HG612 modem stats have recorded a high rate of errors at the time of resyncs caused by the DLM, yet DSLstats shows nothing on any of those 3 days.

[kitz]

So, it seems there were 5559 DS CRC errors & the connection resynced somewhere between the stats being harvested at 09:47 & 09:48


On resyncing, OHFErr counts were reset to zero & cumulative CRC counts continued without being reset.

Assuming the stats following the resync were harvested at say 2 seconds past 09:48, the connection would have been up for 18 - 2 = 16 seconds.

Assuming say 20 seconds for the resync process itself, the resync must have started at around 09:47:24 (36 seconds before 09:47:00)

It would therefore 'appear' that whatever caused the 5559 CRC errors was the cause of the resync.


Once I can see the modem_stats.log data including that resync, I'll be able to decide whether or not to include separate CRC & OHFErr graphs in the FULL__MONTY montage again rather than having a single graph entitled TOTAL DS CRC (OHFerr).

From my router log

Code: [Select]

2 2014 Oct 25 09:48:08 PPPoE notice PPP: ppp1.1 Connection Up.
3 2014 Oct 25 09:48:07 PPPoE notice IPCP Opening.
4 2014 Oct 25 09:48:07 PPPoE notice PPP LCP Up.
5 2014 Oct 25 09:48:07 PPPoE notice PPP LCP Down. Reason:0 lower down
6 2014 Oct 25 09:48:06 PPPoE notice PPP LCP Up.
7 2014 Oct 25 09:48:03 PPPoE notice Receive PADS
8 2014 Oct 25 09:48:03 PPPoE notice Send PADR
9 2014 Oct 25 09:48:03 PPPoE notice PADO received
10 2014 Oct 25 09:48:00 PPPoE notice Send PADI
11 2014 Oct 25 09:47:41 PPPoE notice PPP: ppp1.1 Connection Down.
12 2014 Oct 25 09:47:41 PPPoE notice PPP LCP Down. Reason:0 lower down 
So I definitely lost sync before the errors...   but I just realised HG612stats  supposedly harvested those stats with the errors at 09:48...  at which time I hadnt yet got PPP again until a few seconds later.   

My xDSL log shows that each of the spikes from CRC graphs I posted each occurred at the time of the DLM resyncs.

Code: [Select]

1 2014 Oct 25 09:48:00 XDSL notice VDSL link up. Speed:RX:79987/TX:20000 (Kbps)
2 2014 Oct 25 09:47:32 XDSL notice xDSL PTM link down.
3 2014 Oct 24 07:38:00 XDSL notice VDSL link up. Speed:RX:79987/TX:18999 (Kbps)
4 2014 Oct 24 07:37:31 XDSL notice xDSL PTM link down.
5 2014 Oct 23 10:47:06 XDSL notice VDSL link up. Speed:RX:79987/TX:19001 (Kbps)
6 2014 Oct 23 10:46:40 XDSL notice xDSL PTM link down.

[kitz]

Ive just noticed that the DLM caused me to resync this morning

The DLM is retraining your line after the issues you had with high US errored seconds, it's very normal to have 2 resyncs a day from the DLM it's doing it's best to get your line back to the way is was, have seen that quite a few times when I had line issues 

Cheers NS not querying the DLM resyncs - its the fact that I noticed very high DS CRCs recorded by HG612stats at the time of each of these resyncs (circa 6000 in one minute).. but DSLstats didnt see any of them.  I wondered why HG612 modem stats recorded them, yet there wasnt anything on DSLstats.

[NewtronStar]

Cheers NS not querying the DLM resyncs - its the fact that I noticed very high DS CRCs recorded by HG612stats at the time of each of these resyncs (circa 6000 in one minute).. but DSLstats didnt see any of them.  I wondered why HG612 modem stats recorded them, yet there wasnt anything on DSLstats.

Ok I see was looking at MWS i don't see anything untowards in your stats that could force a resync, it must be false positive in they way the program interprets a normal resync, unfortunately I don't have Modem_Stats on 24/7 only DSLstats so can't replicate your findings sorry.

[Bald_Eagle1]

From my router log

Code: [Select]

2 2014 Oct 25 09:48:08 PPPoE notice PPP: ppp1.1 Connection Up.
3 2014 Oct 25 09:48:07 PPPoE notice IPCP Opening.
4 2014 Oct 25 09:48:07 PPPoE notice PPP LCP Up.
5 2014 Oct 25 09:48:07 PPPoE notice PPP LCP Down. Reason:0 lower down
6 2014 Oct 25 09:48:06 PPPoE notice PPP LCP Up.
7 2014 Oct 25 09:48:03 PPPoE notice Receive PADS
8 2014 Oct 25 09:48:03 PPPoE notice Send PADR
9 2014 Oct 25 09:48:03 PPPoE notice PADO received
10 2014 Oct 25 09:48:00 PPPoE notice Send PADI
11 2014 Oct 25 09:47:41 PPPoE notice PPP: ppp1.1 Connection Down.
12 2014 Oct 25 09:47:41 PPPoE notice PPP LCP Down. Reason:0 lower down 
So I definitely lost sync before the errors...   but I just realised HG612stats  supposedly harvested those stats with the errors at 09:48...  at which time I hadnt yet got PPP again until a few seconds later.   

My xDSL log shows that each of the spikes from CRC graphs I posted each occurred at the time of the DLM resyncs.

Code: [Select]

1 2014 Oct 25 09:48:00 XDSL notice VDSL link up. Speed:RX:79987/TX:20000 (Kbps)
2 2014 Oct 25 09:47:32 XDSL notice xDSL PTM link down.
3 2014 Oct 24 07:38:00 XDSL notice VDSL link up. Speed:RX:79987/TX:18999 (Kbps)
4 2014 Oct 24 07:37:31 XDSL notice xDSL PTM link down.
5 2014 Oct 23 10:47:06 XDSL notice VDSL link up. Speed:RX:79987/TX:19001 (Kbps)
6 2014 Oct 23 10:46:40 XDSL notice xDSL PTM link down.

From what I can gather PPP sessions can hang on even when the connection resyncs.

Likewise, the connection can resync before a new PPP session is initiated (sometimes it isn't even refreshed following a resync).

I suppose it's also possible that your modem/router's system time is slightly out of sync with the PC's system time?


Anyway, the reason HG612 Modem Stats & MDWS report the 5559 CRC errors is that CRC data isn't reset to zero following a resync whereas OHFErr data is reset to zero.

Eric has confirmed that DSLStats reports OHFErr data for CRC errors & I think he uses the same data for the CRC field when uploading the data to MDWS.

HG612 Modem Stats records both OHFErr & CRC data separately.

The data in the CRC (OHFErr) graph is actually from the CRC data (showing those errors).
It appears that MDWS also uses that data.

The OHFErr graph (not currently included in the FULL__MONTY montage) doesn't show it as it was reset to zero at each resync.

Both graphs do show 923 errors at 02:47 24/10/14 though, due to the fact that the connection didn't actually resync at that time.