Filament printed value is reduced on every power cycle

[cdoc83]

Running from commit a1d7816, the 'Filament printed' value consistently drops every time the power is turned off, and later turned back on. This isn't mid-print power cycling, it's completely done with all tasks and stable. I note the value and power down the printer. Some time later, I power up the printer and check the value before a new print. The value is always lower when the printer is powered back on then it was prior to powering down.

Further more, it seems like the value displayed after powering the printer back on is more correct, or at least it more closely matches the estimated value provided by S3D slicing.

[cdoc83]

In case it makes a difference, the 'Printing time' value is not reduced during power cycling. It's just the 'Filament printed' value.

[luc-github]

you mean doing nothing but power off then power on the value of 'Filament printed' changed on LCD screen?

[cdoc83]

Yes, exactly. Read the value, power off, wait a bit, power on, read the value again, value has decreased.

[luc-github]

Well I just did and cannot reproduce
I power up I have 1000
I power off
Wait 30s
I power on => still 1000

[cdoc83]

Are you running v0.92.3.0? Maybe it's already fixed in the latest code? Maybe it only occurs after printing and then powering down?

I have 230 minutes left on a print, once it's done I'll get the exact values.

[luc-github]

no I am running master, which is based on 0.92.10

can test 0.92.3 later

[cdoc83]

Any idea when master will be ready for 1.0A? The read me still indicates it's only for the first generation of printers... I did notice it no longer says not to use it on 1.0A, so it must be getting close?

[luc-github]

It is typo issue in readme, thank for pointing out - I just corrected it - master support 1.0A no worry

[cdoc83]

Oh sweet, thanks!!! I'll be upgrading later today then! Wahoo!

[luc-github]

Do not forget to reset EEPROM after upgrade, it changed a little

[cdoc83]

Cool, thanks for the heads up!!

[cdoc83]

Just wanted to confirm, with v0.92.3.0, I turned on the printer this morning and recorded the filament printed value to be 302.5. I then printed a 4.5 hour job that estimated 11,332.6mm of filament. Once the print was complete and had cooled off for about 30 minutes, the filament printed value was 325.7. I then powered down the printer, waited 20 seconds, and powered on the printer. The value filament printed value is now 314.3. As I also printed a small lego this morning, the 314.3 is almost perfectly inline with the estimated use. I'm now going to upgrade to the latest and print another job to see if it's already resolved.

[cdoc83]

After reflashing v0.92.3.0 just to be sure I ran another test and noticed something peculiar. I started the print at 314.3, and a few seconds before completing the printed filament value was 314.9. As soon as the print completed, the value jumped to 315.4. I flipped through a few menus and went back just to confirm the value was still at 315.4. I then power cycled the printer, and the value was back to 314.9. My next step will be to upgrade to current latest and greatest. I'll return with the results later today.

[cdoc83]

It appears the latest and greatest still has the issue. I started a print at 314.9, estimated use of .5. Just before completing the print, the value was 315.4, but as soon as the print completed the value jumped to 315.9. I power cycled the printer and it was back down to 315.4. Steps to reproduce:

1. Turn on or power cycle the printer
2. Take note of the current filament printed value
3. Start printing something that will use at least half a meter of filament
4. Right before the print completes, take note of the filament printed value
5. Allow the print to complete and cool down
6. Take note of the filament printed value, it should have increased significantly
7. Power cycle the printer
8. Take note of the filament printed value, it should have dropped to approximately the same value as noted in step 4

[cdoc83]

At the very end of the print log, I found this:

READ: Printed filament:315.91m Printing time:5 days 6 hours 46 min

So I belive that's where the 315.9 is being displayed, but as I mentioned as soon as the printer is power cycled, it reverted to the (imo) more correct 315.4.

[cdoc83]

Only place I can find that phrase being used is here: https://github.com/luc-github/Repetier-Firmware-0.92/blob/b64b0701c86de23144d0eced2db32fb3cb5161d5/src/ArduinoDUE/Repetier/Commands.cpp#L383-L385

[luc-github]

this part is pure Repetier FW, I never touched it, I will try to reproduce issue and check the corresponding code

can you export EEPROM after print and export again after power cycle, this will help to see if something else changed

[cdoc83]

I can sure try...

More info: Turns out this is even easier to reproduce... start a print, let it run for maybe 5 minutes and stop the print. Send command M115 and note the printed filament, send command M104 S0 and the printed filament is suddenly higher. The longer it runs, the higher the value jumps. The value is definitely increasing when the M104 command is executed. I'm guessing this is where it begins to corrupt the value: https://github.com/luc-github/Repetier-Firmware-0.92/blob/b64b0701c86de23144d0eced2db32fb3cb5161d5/src/ArduinoDUE/Repetier/Extruder.cpp#L941

[cdoc83]

Is there an easy way to export the EEPROM file? I use S3D to print, but also have repetier server installed if it's easier there.

[luc-github]

ok will check this thanks

for exporting only repetier host has function as far I know

[cdoc83]

Looks like the EEPROM has the correct value all along! Using repetier host I pulled up the EEPROM config and it states Filament printed = 315.570. I run M115 and it reports 315.66. That was after a 2 minute print.

The value from M115 right before executing M104 was 315.57. The report on executing M104 was 315.66. M115 thereafter reports 315.66 as well. After power cycle, M115 reports 315.57 again.

I ran a compare in Notepad++ on pre and post power cycle EEPROM files, they matched perfectly.

[cdoc83]

Once you have a chance to look through things, if it's not in your code let me know what you'd like me to do. I'm happy reporting it over on the repetier repository or letting you do it, don't really care either way.

[luc-github]

repetier may not support it as it is a fork
may I ask to redo your method taking note of value on screen and in EEPROM at same instant?
because screen and EEPROM should be identical at same instant

[cdoc83]

You bet, I'll get back to you shortly!

[cdoc83]

Alright, interesting results...

I reset the filament printed counter and the printer active counter back to 0 in the EEPROM. I started a print and stopped it once approximately 10 centimeters of filament was extruded. The LCD was showing 0.1m filament printed. Upon execution of M115, the printer reported .10m printed filament. Examining the EEPROM showed no value had been recorded yet as it was still 0.

Next I executed M104 S0 to turn off the extruder heat, and was given a report of 0.20m printed filament. The LCD immediately jumped to 0.2m printed filament as well. I then executed M115, which also reported 0.20m printed filament. I then examined EEPROM, which showed a value of .099m printed filament.

I then power cycled the printer, and everything was back in sync. EEPROM contained a value of .099m printed filament, and everything else report .10m printed filament.

Looking at the code, I believe it is simply adding the printed value twice when reporting filament printed. In Eeprom.cpp it takes the current value stored in EEPROM and adds it to the current print's printed filament value, and then stores it over the old value in EEPROM. The problem then arises because the reportPrinterUsage function in Commands also takes the current value in EEPROM and adds it to the current prints printed filament value (which doesn't get reset until the heater is turned back on), and then reports it to the user on the LCD, or over USB.

For example, we start at 25. The current print ticks off up to 50. While the current print is printing, both the LCD and the USB command is accurate, taking 25 and adding the 50, and reporting 75 to the user. However, when the print is finished, we'll say it ticks off up to 200, the firmware takes the current value of 25, adds it to the current print value of 200, and then stores the resulting 225 in EEPROM. The problem now occurs because the current print value isn't reset at this time, so the firmware begins reporting the current value in EEPROM, which is now 225, added to the current print value of 200, reporting 425.

The applicable code flow and locations are as follows:

Command M104 calls Extruder::setTemperatureForExtruder, which if is turning off the heat in turn calls EEPROM::updatePrinterUsage(). In EEPROM::updatePrinterUsage(), the code is executed to store the new value:

https://github.com/luc-github/Repetier-Firmware-0.92/blob/b64b0701c86de23144d0eced2db32fb3cb5161d5/src/ArduinoDUE/Repetier/Eeprom.cpp#L1024

At the end of that function, and if M115 is executed, Commands::reportPrinterUsage() is called. In Commands::reportPrinterUsage() the following code is executed, adding the newly stored EEPROM value to the current print value that hasn't been reset yet:

https://github.com/luc-github/Repetier-Firmware-0.92/blob/b64b0701c86de23144d0eced2db32fb3cb5161d5/src/ArduinoDUE/Repetier/Commands.cpp#L383

I haven't had a chance to implement a potential fix to see if that is in fact the issue, but I think it at least puts us on the right path. We may just need to add the code to reset the current print value, as is done in Extruder::setTemperatureForExtruder when turning on the heat from being off:

https://github.com/luc-github/Repetier-Firmware-0.92/blob/b64b0701c86de23144d0eced2db32fb3cb5161d5/src/ArduinoDUE/Repetier/Extruder.cpp#L946

[cdoc83]

Compared to the base repetier code, all the applicable code is the same. It seems the base repetier code has the bug...

[luc-github]

Good catch - yes as I told you this part I never touched so it is likely a repetier bug

I will follow your method to reproduce it

[luc-github]

reading the code and your evaluation, I think you are right
Printer::filamentPrinted = 0; // new print, new counter is done too late as EEPROM is already update, time is also already reset, and report is requested
should be done before
https://github.com/luc-github/Repetier-Firmware-0.92/blob/5b7f1f5e4bd30e6a5311fc6f13f3c527ca8334f3/src/ArduinoDUE/Repetier/Eeprom.cpp#L1028

[cdoc83]

I agree, I think it would be proper to place the reset right before that line. I will probably throw it in and flash my printer today just to confirm it works as expected with the additional reset. Thanks!

[cdoc83]

Made the change, and it did resolve the issue, but I'm seeing some other oddities now. Going to flash the original code to see if my change is causing other problems. Will report back later.

[luc-github]

Ok thanks

[luc-github]

Any update on this issue ?

[cdoc83]

Yes, my apologies for the delayed response. After reflashing the original code, the other oddities were resolved. I re-added the new line and flashed again, and the issue is now resolved without any additional oddities.

[luc-github]

Thanks for your feedback - I will update this week
You may report it to repetier as it is your finding