Logic LOW and HIGH parts are counted as separate events by pulse_meter

JanneMantyharju commented 2 years ago

The problem

I have an energy meter which blinks light for 200ms for every Watt consumed. I have a light sensor on that light and connected to WeMos D1 Mini with ESP8266 GPIO12. The light sensor inverts the signal so light on in logic low on ESP.

Looking at the code, it should only care about the rising edges, but for reasons I don't know the pulse meter generates event both when the light is on and when it's off. Partial workaround is to set the internal filter to 210ms, so that the constant length led blink is ignored. This however creates a problem that the maximum consumption that can be measured is about 9kW which is enought for the most of the time, but not all the time.

I though the signal to be dirty, but looking at the wave generated by the light sensor with the oscilloscope the edges are sharp.

Which version of ESPHome has the issue?

2022.8.3

What type of installation are you using?

pip

Which version of Home Assistant has the issue?

No response

What platform are you using?

ESP8266

Board

WeMos D1 Mini

Component causing the issue

pulse_meter

Example YAML snippet

No response

Anything in the logs that might be useful for us?

With internal filter disabled, light on creates ~19672 W, followed by the next measurement (light off) which is the actual consumption

[14:39:54][D][sensor:126]: 'House - Power Consumption': Sending state 1722.48804 W with 0 decimals of accuracy
[14:39:54][D][light:035]: 'Red' Setting:
[14:39:54][D][light:046]:   State: ON
[14:39:54][D][sensor:126]: 'House - Daily Energy': Sending state 36.67944 kWh with 3 decimals of accuracy
[14:39:54][D][sensor:126]: 'House - Total Energy': Sending state 0.04400 kWh with 3 decimals of accuracy
[14:39:54][D][light:035]: 'Red' Setting:
[14:39:54][D][light:046]:   State: OFF
[14:39:54][D][sensor:126]: 'House - Power Consumption': Sending state 19780.21875 W with 0 decimals of accuracy
[14:39:54][D][light:035]: 'Red' Setting:
[14:39:54][D][light:046]:   State: ON
[14:39:54][D][sensor:126]: 'House - Daily Energy': Sending state 36.68044 kWh with 3 decimals of accuracy
[14:39:54][D][sensor:126]: 'House - Total Energy': Sending state 0.04500 kWh with 3 decimals of accuracy
[14:39:54][D][light:035]: 'Red' Setting:
[14:39:54][D][light:046]:   State: OFF
[14:39:56][D][sensor:126]: 'House - Power Consumption': Sending state 1724.13794 W with 0 decimals of accuracy
[14:39:56][D][light:035]: 'Red' Setting:
[14:39:56][D][light:046]:   State: ON
[14:39:56][D][sensor:126]: 'House - Daily Energy': Sending state 36.68144 kWh with 3 decimals of accuracy
[14:39:56][D][sensor:126]: 'House - Total Energy': Sending state 0.04600 kWh with 3 decimals of accuracy
[14:39:56][D][light:035]: 'Red' Setting:
[14:39:57][D][light:046]:   State: OFF
[14:39:57][D][sensor:126]: 'House - Power Consumption': Sending state 19672.13281 W with 0 decimals of accuracy
[14:39:57][D][light:035]: 'Red' Setting:
[14:39:57][D][light:046]:   State: ON
[14:39:57][D][sensor:126]: 'House - Daily Energy': Sending state 36.68243 kWh with 3 decimals of accuracy
[14:39:57][D][sensor:126]: 'House - Total Energy': Sending state 0.04700 kWh with 3 decimals of accuracy
[14:39:57][D][light:035]: 'Red' Setting:
[14:39:57][D][light:046]:   State: OFF
[14:39:59][D][sensor:126]: 'House - Power Consumption': Sending state 1721.66431 W with 0 decimals of accuracy
[14:39:59][D][light:035]: 'Red' Setting:
[14:39:59][D][light:046]:   State: ON
[14:39:59][D][sensor:126]: 'House - Daily Energy': Sending state 36.68343 kWh with 3 decimals of accuracy
[14:39:59][D][sensor:126]: 'House - Total Energy': Sending state 0.04800 kWh with 3 decimals of accuracy
[14:39:59][D][light:035]: 'Red' Setting:
[14:39:59][D][light:046]:   State: OFF
[14:39:59][D][sensor:126]: 'House - Power Consumption': Sending state 19672.13281 W with 0 decimals of accuracy
[14:39:59][D][light:035]: 'Red' Setting:
[14:39:59][D][light:046]:   State: ON
[14:39:59][D][sensor:126]: 'House - Daily Energy': Sending state 36.68441 kWh with 3 decimals of accuracy
[14:39:59][D][sensor:126]: 'House - Total Energy': Sending state 0.04900 kWh with 3 decimals of accuracy
[14:39:59][D][light:035]: 'Red' Setting:

Additional information

No response

jbbjarnason commented 2 years ago

How about counting both low and high and divide by 2? Or count 100 for each edge?

JanneMantyharju commented 2 years ago

Dividing by two would work for total consumption, because every blink == 1 W consumed. It would not solve the problem for current consumption. For that you need to time how long the led is OFF. The led is always on for 200ms regardless of the consumption.

mrestorff commented 1 year ago

This is an issue I've been having ever since trying to get readings from my gas meter using a reed switch.

My understanding is that the pulse_meter should only count the raising edges in both its internal_filter_mode settings. However, the default EDGE mode counts every pulse twice. Using a binary_sensor with the same delayed_on value as the internal_filter on the pulse_meter sensor (100ms), the issue becomes clearly visible: Screenshot 2023-01-01 191916

I was able to get better results with the PULSE mode, but that one is only suitable if you have reliably long pulses, which often isn't the case with water/gas meters.

As the pulse_meter was implemented with PR 1434 and the filter mode was introduced by PR 3082, maybe @stevebaxter or @cstaahl could shine some light on this?

I'd love for this sensor to be usable for these applications, as it would simplify things immensely.

cstaahl commented 1 year ago

@mrestorff and @JanneMantyharju There have been some improvements on the pulse_meter since this was posted. Can you try with sensor in internal_filter_mode: "PULSE" and also add this to the .yaml to make sure it uses the most recent version of the code?

external_components:
  - source: github://pr#4199
    components: [ pulse_meter ]

mrestorff commented 1 year ago

Thanks, @cstaahl, for the heads-up. I did a 12h test with the code from PR 4199, and it works flawlessly in PULSE mode. The output is the same as using a binary_sensor in conjunction with a template_sensor counting up, which is the expected behaviour (imo). The previous issue with long activations (>60s) is gone. This is awesome, thanks a lot @cstaahl!

That being said, EDGE mode still counts each pulse twice. I can't imagine this being specific to my implementation, as I've seen multiple reports of this happening. As an intermediate fix, a hint in the documentation could avoid hours of debugging for people starting to use this sensor, or even changing the default internal_filter_mode to PULSE.

I did see PR 4231 further improving on the sensor, but that doesn't address the EDGE mode issue from my testing.

cstaahl commented 1 year ago

@mrestorff Good that the pulse mode is working for you. So did the PR4231 fix the issue in EDGE mode for you, or was it the same result with double counting?

mrestorff commented 1 year ago

@cstaahl No, that didn't fix EDGE mode, unfortunately. It's still counting double (and occasionally triple).

cstaahl commented 1 year ago

@mrestorff Could you post a snippet of the log output of the pulse_meter in EDGE mode alongside the binary_sensor? Ideally the first ten pulses or so after boot up. Can you also post the yaml configuration you are using?

mrestorff commented 1 year ago

@cstaahl Sure thing. Curiously, I'm not getting any VERY_VERBOSE logs from pulse_meter if it's set to EDGE mode. Other components are logging at the correct level. In PULSE mode, I get the occasional [18:18:09][VV][pulse_meter:158]: State is now high and the like. I tried re-flashing, but the issue persists.

Here's the current log output directly after startup:

[17:21:13][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.000000
[17:21:22][V][sensor:076]: 'Total Gas Consumption': Received new state 1.000000
[17:21:22][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:21:28][V][sensor:076]: 'Total Gas Consumption': Received new state 2.000000
[17:21:28][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:21:28][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.010000
[17:22:11][V][sensor:076]: 'Total Gas Consumption': Received new state 3.000000
[17:22:11][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:22:13][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.020000
[17:22:19][V][sensor:076]: 'Total Gas Consumption': Received new state 4.000000
[17:22:19][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:22:33][V][sensor:076]: 'Total Gas Consumption': Received new state 5.000000
[17:22:33][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:22:35][V][sensor:076]: 'Total Gas Consumption': Received new state 6.000000
[17:22:35][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:22:58][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.030000
[17:23:50][D][pulse_meter:043]: No pulse detected for 75s, assuming 0 pulses/min
[17:24:38][V][sensor:076]: 'Total Gas Consumption': Received new state 7.000000
[17:24:38][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:24:43][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.040000
[17:24:48][V][sensor:076]: 'Total Gas Consumption': Received new state 8.000000
[17:24:48][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:26:03][D][pulse_meter:043]: No pulse detected for 75s, assuming 0 pulses/min
[17:26:13][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.040000
[17:26:31][V][sensor:076]: 'Total Gas Consumption': Received new state 9.000000
[17:26:31][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:26:40][V][sensor:076]: 'Total Gas Consumption': Received new state 10.000000
[17:26:40][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:26:43][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.050000
[17:27:55][D][pulse_meter:043]: No pulse detected for 75s, assuming 0 pulses/min
[17:27:56][V][sensor:076]: 'Total Gas Consumption': Received new state 11.000000
[17:27:56][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:27:58][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.060000
[17:28:05][V][sensor:076]: 'Total Gas Consumption': Received new state 12.000000
[17:28:05][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:28:13][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.060000
[17:28:52][V][sensor:076]: 'Total Gas Consumption': Received new state 13.000000
[17:28:52][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:28:58][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.070000
[17:29:02][V][sensor:076]: 'Total Gas Consumption': Received new state 14.000000
[17:29:02][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:29:13][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.070000
[17:29:47][V][sensor:076]: 'Total Gas Consumption': Received new state 15.000000
[17:29:47][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:29:54][V][sensor:076]: 'Total Gas Consumption': Received new state 16.000000
[17:29:54][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:29:58][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.080000
[17:30:34][V][sensor:076]: 'Total Gas Consumption': Received new state 17.000000
[17:30:34][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[17:30:43][V][sensor:076]: 'Total Gas Consumption': Received new state 18.000000
[17:30:43][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[17:30:43][V][sensor:076]: 'Total Gas Consumption - from binary_sensor': Received new state 0.090000

And here's the relevant part of my current config:

substitutions:
  filter_duration: "100ms" # avoid erroneous readings

binary_sensor:
  - platform: gpio
    name: "${friendly_name} Pulse"
    id: internal_pulse_counter
    internal: true
    disabled_by_default: true
    pin:
      number: ${pulse_pin}
      mode: INPUT_PULLUP
      inverted: true
    filters:
      - delayed_on_off: ${filter_duration}

sensor:
  # Gas meter
  - platform: pulse_meter
    id: ${devicename}_current_consumption
    name: "${friendly_name} current consumption"
    icon: "mdi:fire"
    unit_of_measurement: "m³/h"
    pin:
      number: ${pulse_pin}
      mode: INPUT_PULLUP
    internal_filter: ${filter_duration}
    internal_filter_mode: EDGE
    timeout: 75s
    filters:
      - multiply: 0.06
    accuracy_decimals: 2
    total:
      id: ${devicename}_consumption
      name: "Total gas consumption"
      state_class: total_increasing
      device_class: gas
      unit_of_measurement: "m³"
      accuracy_decimals: 3
      filters:
        - multiply: ${pulse_corresponds_to}

cstaahl commented 1 year ago

@mrestorff thank you! What version of ESPHome did you use for the test and did you configure any external_components for the pulse_meter? Yes, the code handling the EDGE mode does not have any very verbose messages defined. PULSE mode had the messages because there were a couple issues that arose that were hard to reproduce and debug.

mrestorff commented 1 year ago

@cstaahl Sorry, I forgot to mention that. I configured PR 4199 as external component.

mrestorff commented 1 year ago

A quick update from my testing of the PULSE mode: It still misses some pulses, unfortunately. In 72 hours, it has missed 31 out of 1318 pulses. That's not too bad, but still doesn't match the behaviour of a binary_sensor with an on/off delay. The pulses are usually >8 seconds long, with some possible flickering at the edges. I'm using PR4199 by @cstaahl as external component.

TrentHouliston commented 1 year ago

Hi, @mrestorff would you be able to try PR 4231 and see if its pulse mode causes the issue as well?

mrestorff commented 1 year ago

Hi @TrentHouliston, thanks for chiming in! I tried that tonight with the same results, unfortunately. Still missing about 2% of all pulses.

The setup is the same as the one I posted above, and the missed pulses don't occur on any edge cases (like extremely long activations due to the magnet stopping right above the reed contact), but rather randomly in between pulses with the usual length of 8–15 seconds.

TrentHouliston commented 1 year ago

@mrestorff I've quickly made a version of the code that will print out every single interrupt that happens. We should be able to use this information to identify why it's missing pulses with this. Hopefully, the ESP can keep up with the log rate (depending on how frequent/noisy the pulses are).

@cstaahl If this shows a problem the data could also be good for you to include in the unit tests you're writing.

external_components:
  - source: github://TrentHouliston/esphome@log_interrupts
    components: [ pulse_meter ]

mrestorff commented 1 year ago

@TrentHouliston Here are two examples of a missed pulse and the following two pulses, which were counted correctly. The 'interim' sensor is based on the binary_sensor, the other one is from the pulse_meter.

[09:18:25][D][pulse_meter:042]: ISR: 38535733 0 0 0 0 0
[09:18:25][D][pulse_meter:042]: ISR: 38535766 1 0 1 0 0
[09:18:25][D][pulse_meter:042]: ISR: 38535789 0 1 0 0 0
[09:18:25][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[09:18:26][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.01000 m³ with 3 decimals of accuracy
[09:18:35][D][pulse_meter:042]: ISR: 48205971 1 0 1 0 0
[09:18:35][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[09:19:23][D][pulse_meter:042]: ISR: 96436929 0 1 1 0 1
[09:19:23][D][pulse_meter:042]: ISR: 96436962 1 0 0 1 1
[09:19:23][D][pulse_meter:042]: ISR: 96436986 0 1 0 1 1
[09:19:23][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[09:19:24][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.02000 m³ with 3 decimals of accuracy
[09:19:33][D][pulse_meter:042]: ISR: 106039214 1 0 1 1 0
[09:19:33][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.01000 m³ with 3 decimals of accuracy
[09:19:33][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[09:20:21][D][pulse_meter:042]: ISR: 154466233 0 1 1 0 1
[09:20:21][D][pulse_meter:042]: ISR: 154466266 1 0 0 1 1
[09:20:21][D][pulse_meter:042]: ISR: 154466290 0 1 0 1 1
[09:20:21][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[09:20:22][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.03000 m³ with 3 decimals of accuracy
[09:20:31][D][pulse_meter:042]: ISR: 164085916 1 0 1 1 0
[09:20:31][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.02000 m³ with 3 decimals of accuracy
[09:20:31][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF

The second one:

[09:47:38][D][sensor:127]: 'sensor_uptime': Sending state 539.26599 s with 0 decimals of accuracy
[09:47:47][D][pulse_meter:042]: ISR: 547090142 0 1 1 0 1
[09:47:47][D][pulse_meter:042]: ISR: 547090174 1 0 0 1 1
[09:47:47][D][pulse_meter:042]: ISR: 547090199 0 1 0 1 1
[09:47:47][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[09:47:47][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.10000 m³ with 3 decimals of accuracy
[09:47:55][D][pulse_meter:042]: ISR: 555991537 0 0 0 1 1
[09:47:55][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[09:48:40][D][pulse_meter:042]: ISR: 600692784 0 0 0 1 1
[09:48:40][D][pulse_meter:042]: ISR: 600692817 1 0 1 1 0
[09:48:40][D][pulse_meter:042]: ISR: 600692841 0 1 0 0 0
[09:48:40][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.10000 m³ with 3 decimals of accuracy
[09:48:40][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[09:48:41][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.11000 m³ with 3 decimals of accuracy
[09:48:49][D][pulse_meter:042]: ISR: 609599498 1 0 1 0 0
[09:48:49][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[09:49:34][D][pulse_meter:042]: ISR: 654518330 0 1 1 0 1
[09:49:34][D][pulse_meter:042]: ISR: 654518362 1 0 0 1 1
[09:49:34][D][pulse_meter:042]: ISR: 654518387 0 1 0 1 1
[09:49:34][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[09:49:35][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.12000 m³ with 3 decimals of accuracy
[09:49:43][D][pulse_meter:042]: ISR: 663557542 1 0 1 1 0
[09:49:43][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.11000 m³ with 3 decimals of accuracy
[09:49:43][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF

mrestorff commented 1 year ago

Here's an even more severe example, where several consecutive pulses were missed:

[11:11:39][D][pulse_meter:042]: ISR: 2284637308 0 1 1 0 1
[11:11:39][D][pulse_meter:042]: ISR: 2284637341 1 0 0 1 1
[11:11:39][D][pulse_meter:042]: ISR: 2284637366 0 1 0 1 1
[11:11:39][D][pulse_meter:042]: ISR: 2284637411 0 0 0 1 1
[11:11:39][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:11:39][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.28000 m³ with 3 decimals of accuracy
[11:11:47][D][pulse_meter:042]: ISR: 2292724582 1 0 1 1 0
[11:11:47][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.26000 m³ with 3 decimals of accuracy
[11:11:47][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:12:28][D][pulse_meter:042]: ISR: 2334114365 0 1 1 0 1
[11:12:28][D][pulse_meter:042]: ISR: 2334114398 1 0 0 1 1
[11:12:28][D][pulse_meter:042]: ISR: 2334114423 0 1 0 1 1
[11:12:28][D][pulse_meter:042]: ISR: 2334114468 1 0 0 1 1
[11:12:28][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:12:29][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.29000 m³ with 3 decimals of accuracy
[11:12:36][D][pulse_meter:042]: ISR: 2342443356 1 1 0 1 1
[11:12:36][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:13:19][D][pulse_meter:042]: ISR: 2385541587 0 1 1 1 1
[11:13:19][D][pulse_meter:042]: ISR: 2385541620 1 0 0 1 1
[11:13:19][D][pulse_meter:042]: ISR: 2385541644 0 1 0 1 1
[11:13:19][D][pulse_meter:042]: ISR: 2385541690 0 0 0 1 1
[11:13:19][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:13:21][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.30000 m³ with 3 decimals of accuracy
[11:13:28][D][pulse_meter:042]: ISR: 2394288847 1 0 1 1 0
[11:13:28][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.27000 m³ with 3 decimals of accuracy
[11:13:28][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:14:12][D][pulse_meter:042]: ISR: 2438411980 0 1 1 0 1
[11:14:12][D][pulse_meter:042]: ISR: 2438412013 1 0 0 1 1
[11:14:12][D][pulse_meter:042]: ISR: 2438412038 0 1 0 1 1
[11:14:12][D][pulse_meter:042]: ISR: 2438412084 0 0 0 1 1
[11:14:12][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:14:13][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.31000 m³ with 3 decimals of accuracy
[11:14:21][D][pulse_meter:042]: ISR: 2447256602 1 0 1 1 0
[11:14:21][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.28000 m³ with 3 decimals of accuracy
[11:14:21][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:15:06][D][pulse_meter:042]: ISR: 2492144855 0 1 1 0 1
[11:15:06][D][pulse_meter:042]: ISR: 2492144888 1 0 0 1 1
[11:15:06][D][pulse_meter:042]: ISR: 2492144913 0 1 0 1 1
[11:15:06][D][pulse_meter:042]: ISR: 2492144958 1 0 0 1 1
[11:15:06][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:15:07][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.32000 m³ with 3 decimals of accuracy
[11:15:15][D][pulse_meter:042]: ISR: 2501286581 1 1 0 1 1
[11:15:15][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:16:01][D][pulse_meter:042]: ISR: 2547386267 0 1 1 1 1
[11:16:01][D][pulse_meter:042]: ISR: 2547386300 1 0 0 1 1
[11:16:01][D][pulse_meter:042]: ISR: 2547386325 0 1 0 1 1
[11:16:01][D][pulse_meter:042]: ISR: 2547386370 0 0 0 1 1
[11:16:01][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:16:03][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.33000 m³ with 3 decimals of accuracy
[11:16:10][D][pulse_meter:042]: ISR: 2556568496 1 0 1 1 0
[11:16:10][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.29000 m³ with 3 decimals of accuracy
[11:16:10][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:16:57][D][pulse_meter:042]: ISR: 2603228622 0 1 1 0 1
[11:16:57][D][pulse_meter:042]: ISR: 2603228655 1 0 0 1 1
[11:16:57][D][pulse_meter:042]: ISR: 2603228680 0 1 0 1 1
[11:16:57][D][pulse_meter:042]: ISR: 2603228726 0 0 0 1 1
[11:16:57][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:16:59][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.34000 m³ with 3 decimals of accuracy
[11:17:06][D][pulse_meter:042]: ISR: 2612575901 1 0 1 1 0
[11:17:06][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.30000 m³ with 3 decimals of accuracy
[11:17:06][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:17:54][D][pulse_meter:042]: ISR: 2659868174 0 1 1 0 1
[11:17:54][D][pulse_meter:042]: ISR: 2659868207 1 0 0 1 1
[11:17:54][D][pulse_meter:042]: ISR: 2659868232 0 1 0 1 1
[11:17:54][D][pulse_meter:042]: ISR: 2659868278 0 0 0 1 1
[11:17:54][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:17:55][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.35000 m³ with 3 decimals of accuracy
[11:18:03][D][pulse_meter:042]: ISR: 2669316909 1 0 1 1 0
[11:18:03][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.31000 m³ with 3 decimals of accuracy
[11:18:03][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:18:51][D][pulse_meter:042]: ISR: 2717233800 0 1 1 0 1
[11:18:51][D][pulse_meter:042]: ISR: 2717233833 1 0 0 1 1
[11:18:51][D][pulse_meter:042]: ISR: 2717233858 0 1 0 1 1
[11:18:51][D][pulse_meter:042]: ISR: 2717233904 1 0 0 1 1
[11:18:51][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:18:53][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.36000 m³ with 3 decimals of accuracy
[11:19:01][D][pulse_meter:042]: ISR: 2726767370 1 1 0 1 1
[11:19:01][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:19:49][D][pulse_meter:042]: ISR: 2775107917 0 1 1 1 1
[11:19:49][D][pulse_meter:042]: ISR: 2775107950 1 0 0 1 1
[11:19:49][D][pulse_meter:042]: ISR: 2775107975 0 1 0 1 1
[11:19:49][D][pulse_meter:042]: ISR: 2775108020 1 0 0 1 1
[11:19:49][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:19:51][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.37000 m³ with 3 decimals of accuracy
[11:19:59][D][pulse_meter:042]: ISR: 2784676015 1 1 0 1 1
[11:19:59][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:20:47][D][pulse_meter:042]: ISR: 2833543914 0 1 1 1 1
[11:20:47][D][pulse_meter:042]: ISR: 2833543947 1 0 0 1 1
[11:20:47][D][pulse_meter:042]: ISR: 2833543972 0 1 0 1 1
[11:20:47][D][pulse_meter:042]: ISR: 2833544017 1 0 0 1 1
[11:20:47][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:20:49][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.38000 m³ with 3 decimals of accuracy
[11:20:57][D][pulse_meter:042]: ISR: 2843253115 1 1 0 1 1
[11:20:57][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF
[11:21:46][D][pulse_meter:042]: ISR: 2892357520 0 1 1 1 1
[11:21:46][D][pulse_meter:042]: ISR: 2892357553 1 0 0 1 1
[11:21:46][D][pulse_meter:042]: ISR: 2892357578 0 1 0 1 1
[11:21:46][D][pulse_meter:042]: ISR: 2892357623 0 0 0 1 1
[11:21:46][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state ON
[11:21:47][D][sensor:127]: 'Gas Meter Total Consumption - interim': Sending state 0.39000 m³ with 3 decimals of accuracy
[11:21:56][D][pulse_meter:042]: ISR: 2902155597 1 0 1 1 0
[11:21:56][D][sensor:127]: 'Gas Meter Total Consumption': Sending state 0.32000 m³ with 3 decimals of accuracy
[11:21:56][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF

TrentHouliston commented 1 year ago

Ok, so it appears what is happening is that it's reaching either the end (or the start) of a pulse and the ISR is firing but it's reading the wrong value. I'm guessing the transitions in/out are noisy and it's making phantom interrupts.

My guess is that the following situation is occurring (and visa versa happening at the other end):

We are currently in a pulse
The pin goes low triggering an interrupt
The pin goes high due to a noisy transition
The ISR reads high so discounts the update since no change in the pin happened
The next pulse in the future starts with a rising edge (again no change from the perspective of the code)
The two pulses are merged into one

These are the "phantom" interrupts that are quite irritating to deal with since they result in your pin values being different than you'd expect.

The reason the binary sensor doesn't suffer from this problem is that it's constantly polling the pin value rather than relying on interrupts, so eventually, it will see that the pin value is low and respond accordingly.

I was hoping that multiple interrupts would occur when this happened so that eventually you'd read the correct value, but it looks like that is not the case.

I think the only real way to deal with this is to read the pin value in the main loop as well and find a way to introduce that into the filter.

cstaahl commented 1 year ago

The "phantom" interrupts are a pain, but I think they are handleable with the code you have @TrentHouliston. I haven't been able go through all of the logs in detail, but I will when I have the time at hand and correct and amend the unit tests if necessary.

One additional thing caught my eye though, and this will be an even tougher nut to crack and perhaps force us to use the loop() to verify and correct the state we are in.

In the logs, rising edges seem to be always clean, as there is only ever one interrupt. However, the pin_val value is not consistent. Most of the times we see something like this:

[11:21:56][D][pulse_meter:042]: ISR: 2902155597 1 0 1 1 0
[11:21:56][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF

which is correct, because the pin value of the binary sensor is inverted. However, there is one entry like this (and I bet it will have happened more than once)

[09:47:55][D][pulse_meter:042]: ISR: 555991537 0 0 0 1 1
[09:47:55][D][binary_sensor:036]: 'Gas Meter Pulse': Sending state OFF

This will cause the pulse_meter to get out of sync and probably causes the logic to handle the jitter at the rising and falling edges incorrectly because it is treating a rising edge as a falling and vice versa. As long as there is at least one correct pin reading per edge and we are in sync with the high / low state, I think we can filter out the phantom readings with your logic. However once we get out of sync, it is just guess work....

We may even consider setting the pulse_meter to work with a binary sensor as an internal member in PULSE mode that polls the pin value every loop(). In that case we would have to either limit the internal_filter value to about 50ms (which is about the interval at which the loop() is called) or switch to the logic with ISR if the internal_filter value is set below a threshold with some kind of warning or hint to the user.

To be honest, I think using a less accurate but more robust approach with a binary sensor may cover a majority of use cases for the pulse_meter. Of course, keeping EDGE mode and perhaps the "high performance" pulse mode mentioned above for highly accurate and high frequency uses cases.

esphome / issues