DDA & Move Debugging

[petriheino]

Im trying to debug move commands

1. Nothing with M111 S1 P6 ;DDA logging
2. Nothing with M111 S1 P4 ;Move logging
3. Only works with both P6 & P4 on

When both P6 & P4 is enabled, im getting this type of debug info via USB serial, two or more blocks of data repeating as below.

pr 1 ts=512267325 DDA: start=[186.160995 83.862999 7.200000] end=[185.625000 84.664001 7.200000] s=0.963793 vec=[-0.556132 0.831094 0.000000 0.000000 0.000000]
2021-09-12 23:46:28,086 - a=600.000000 d=600.000000 reqv=15.416668 startv=15.416668 topv=15.416668 endv=15.416668
2021-09-12 23:46:28,087 - cks=58609 sstcda=24088 tstcddpdsc=82697 exac=0
2021-09-12 23:46:28,088 - DM0: dir=F steps=79 next=1 rev=80 interval=740 2dtstc2diva=0
2021-09-12 23:46:28,090 - accelStopStep=1 decelStartStep=80 2c2mmsda=35681189 2c2mmsdd=35681189
2021-09-12 23:46:28,092 - mmPerStepTimesCdivtopSpeed=758400 fmsdmtstdca2=0 cc=56250 acc=0
2021-09-12 23:46:28,094 - DMY: dir=F steps=64 next=1 rev=65 interval=915 2dtstc2diva=0
2021-09-12 23:46:28,096 - accelStopStep=1 decelStartStep=65 2c2mmsda=44118924 2c2mmsdd=44118924
2021-09-12 23:46:28,097 - mmPerStepTimesCdivtopSpeed=937744 fmsdmtstdca2=0 cc=0 acc=0
2021-09-12 23:46:28,101 - DMX: dir=B steps=43 next=1 rev=44 interval=1363 2dtstc2diva=0
2021-09-12 23:46:28,103 - accelStopStep=1 decelStartStep=44 2c2mmsda=65665377 2c2mmsdd=65665377
2021-09-12 23:46:28,106 - mmPerStepTimesCdivtopSpeed=1395712 fmsdmtstdca2=0 cc=0 acc=0
2021-09-12 23:46:28,111 - Transformed 163.43 77.45 7.20 to 13074 6196 2880

Can this info be read to check what was the requested motor move for extruder? Because after each gcode theres more than one output logging info block similar to above, which one should be read?

Is it intentional that if not both S6 and S4 are enabled, there is no debug info? Now both M111 S1 P6 ;DDA debug and M111 S1 P4 ;Move debug has to be enabled to get any data.

[dc42]

@petriheino enabling Move debug enables some types of debug info, and enabling DDA debug enables other types. It's intentional that you only get every move printed out of you enable both.

Now that we can set variable debug levels in M111, I will probably combine the Move and DDA debug facilities in a future release.

[petriheino]

@dc42

Observing extruder movements, Im thinking there could be 0.1s delay after unretraction before it starts moving.

Could you take a look at these logs that could error be found in there?

Layer Z7.4 single loops Pronterface log.txt
Layer Z7.4 single loops.gcode

[petriheino]

@dc42

Looking with logic analyzer

Trigger GPIO pin configured M950 P8 C"EXP.E3STOP"
Drive E0 measured with config.g: M569 P3 S1 R-1

single loops test with trigger.gcode

G11
M118 P1 S"Un-Retract done" 

;Unretraction, turn on
M42 P8 S1 ;GPIO 8 = Trigger on

G1 X163.467 Y76.489 E0.0357 F925
G1 X163.580 Y75.532 E0.0357
G1 X163.768 Y74.588 E0.0357
G1 X164.030 Y73.660 E0.0357

Measured step signal lenght 2μs +- 0.5μs
Also, every now and then (every 1ms or so) signal lenght 7μs.

Is it normal that step lenght varies?

[petriheino]

@dc42
Is it normal that E0 EN pin is turned on/off like this? Doesnt this mean that the driver is powered on/off constantly?

[dc42]

@petriheino what board is it?

[petriheino]

@dc42
Hi, its a Duet 2 Wifi 1.04c (sticker on MCU: 819.1845) its official board, brand new, (not used before) (I can send receipt via PM/email, I have over 20pcs new boards so I can repeat test if needed)

Today, I repeated the test with another logic analyzer pins, and with re-flashed RRF v3.3 release version, giving same results.

1. If board is just powered on / restarted with M999, then EN is constantly High
2. As soon as print is started, it starts pulling it low in approx 17μs 10kHz
3. This also fits the problem description of having gaps in prints (No motor movements, or un-constant results during retraction moves)
4. No difference if print run via Pronterface or WebUI
5. No difference if M552 S-1 or M552 S1 (wifi off/on)

How should we fix this?

SENDING:M122
=== Diagnostics ===
RepRapFirmware for Duet 2 WiFi/Ethernet version 3.3 (2021-06-15 21:44:54) running on Duet WiFi 1.02 or later
Board ID: 08DGM-917NK-F23T0-6J1FJ-3SN6N-TD88G
Used output buffers: 1 of 24 (2 max)
=== RTOS ===
Static ram: 23876
Dynamic ram: 75104 of which 0 recycled
Never used RAM 15436, free system stack 186 words
Tasks: NETWORK(ready,10.7%,376) HEAT(delaying,0.0%,341) Move(notifyWait,0.1%,364) MAIN(running,86.3%,467) IDLE(ready,2.9%,29), total 100.0%
Owned mutexes: USB(MAIN)
=== Platform ===
Last reset 00:00:31 ago, cause: power up
Last software reset time unknown, reason: HardFault, GCodes spinning, available RAM 38776, slot 0
Software reset code 0x0063 HFSR 0x40000000 CFSR 0x00000001 ICSR 0x00400803 BFAR 0xe000ed38 SP 0x20002318 Task MAIN Freestk 767 ok
Stack: 00000000 20009ca9 20009bdf d5fc07da ffffffff 0040e7b3 d5fc07da 40070000 20009cc8 200023e0 2000b908 2000b974 00000015 0043371b 00000022 2000b974 200023e0 00000000 0000000f 00455bfb a5a5a5a5 200024e8 20005df0 20005f1d 20005df0 0040e7b3 20005f1d
Error status: 0x00
Error status: 0x00

Aux0 errors 0,0,0
Step timer max interval 0
MCU temperature: min 23.8, current 25.8, max 26.1
Supply voltage: min 1.4, current 1.7, max 1.7, under voltage events: 0, over voltage events: 0, power good: no
Heap OK, handles allocated/used 0/0, heap memory allocated/used/recyclable 0/0/0, gc cycles 0
Driver 0: position 0, ok, SG min/max not available
Driver 1: position 0, ok, SG min/max not available
Driver 2: position 0, ok, SG min/max not available
Driver 3: position 0, ok, SG min/max not available
Driver 4: position 0, ok, SG min/max not available
Driver 5: position 0
Driver 6: position 0
Driver 7: position 0
Driver 8: position 0
Driver 9: position 0
Driver 10: position 0
Driver 11: position 0
Date/time: 1970-01-01 00:00:00
Cache data hit count 1347386356
Slowest loop: 5.01ms; fastest: 0.13ms
I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0
=== Storage ===
Free file entries: 10
SD card 0 detected, interface speed: 20.0MBytes/sec
SD card longest read time 3.2ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 83, maxWait 0ms, bed compensation in use: none, comp offset 0.000
=== MainDDARing ===
Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== AuxDDARing ===
Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters = -1 -1 -1 -1, chamberHeaters = -1 -1 -1 -1
=== GCodes ===
Segments left: 0
Movement lock held by null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is ready with "M122" in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
Daemon is idle in state(s) 0
Autopause is idle in state(s) 0
Code queue is empty.
=== Network ===
Slowest loop: 15.76ms; fastest: 0.00ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0), 0 sessions
HTTP sessions: 0 of 8
- WiFi -
Network state is active
WiFi module is connected to access point
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 1.23
WiFi MAC address 84:0d:8e:b2:f4:67
WiFi Vcc 3.39, reset reason Turned on by main processor
WiFi flash size 4194304, free heap 25152
WiFi IP address 192.168.86.240
WiFi signal strength -58dBm, mode none, reconnections 0, sleep mode modem
Clock register ffffffff
Socket states: 0 0 0 0 0 0 0 0

[dc42]

@petriheino the signal you are calling E0_EN isn't an enable signal at all, it's the SPI chip select signal to the TMC2660 driver. It goes low while the microcontroller is talking to it over SPI. Enabling and disabling a TMC2660 driver is done using SPI commands.

The corresponding lines on the expansion bus are chip select signals when they are connected to TMC2660 drivers on a DueX expansion board, and Enable signals when they are connected to external drivers instead.

[petriheino]

@dc42
Thats true, its also seen on the schematics.

From TMC2660 datasheet:
When CSN goes high, the contents of the internal shift register are latched into the internal control register

Could this affect the motor performance negatively?

[dc42]

@petriheino said in DDA & Move Debugging:

Could this affect the motor performance negatively?

No, we'd see a lot more problems if it did.

[petriheino]

@dc42
Well there is some serious issues with retraction points, extrusion evenness, gaps in prints.
Maybe it could be worth a try to disable this?
Could we try it?
Is there some 10kHz SPI loop to the driver that could be disabled?
(I can compile custom FW if needed)

[dc42]

@petriheino that isn't a solution to your issue. The TMC drivers are designed to operate with SPI transactions. Just think of the problems there would be with axis motion if SPI comms affected movement of the motors.

I suggest you post photos of your prints to show what extrusion issues you are having. Try with pressure advance disabled initially in case excessive PA is part of the problem. Also make sure you don't have coast to end or pressure adjustment enabled in the slicer. And tell us what extruder you are using and what its steps/mm is.

[petriheino]

@dc42

If you believe its a issue related to settings / extruder, then please send info about recommended setup or what type of extruder are you using to test. I can mount any type of extruder in that case and repeat the tests.

Now its running on direct extruder, 143steps/mm in 16x microstepping. It was made to 256x because RRF is failing to keep position of extruder, tested with test script as below

M350 X16 Y16 Z16 I1		; Microstepping X Y Z
M350 E256 I0			; Microstepping E
M92 X80.00 Y80.00 Z400.0 E2210.000; set steps per mm

12 - Test E max Acceleration.gcode

With this test, mount indicator on rotor, and check if it returns to starting position. RRF fails if using absolute mode, but relative extrusion works, as long as theres enough steps/mm.

The maximum for my extruder (safe values, it can do also approx 30% more):

M566 E3000		;instantaneous speed change / Jerk (mm/min)
M203 E6000		;max speeds (mm/min)
M201 E9000		;accelerations (mm/s^2)

Print error is that, theres always gaps in the print, and very rough retraction points and wavy walls, and gaps in solid infills.

[petriheino]

@dc42
Some pictures

[petriheino]

@dc42 Mismatching step amounts measured with logic analyzer

Note: in pictures there is signal 1&2 AS5040 encoder (10-bit quadrature A&B)
Signal 3: E0 DIR. Signal 4: E0 STEP. Signal 5: Not connected. Signal 6: E0 CS.

Retraction event, reverses 699 steps

Un-rectraction event, 656 steps

Start of printing

This is with M572 D0 S0.06 and M207 S0.30 F1200 Z0.1. It is very fine tuned setting, and print error is much worse if using bigger retraction distance.

Here is comparison how it takes time to recover after un-retraction. at 699 steps there should be finally filament back at nozzle, but we have already lost several tens of microseconds of printing.

RRF v 3.3.

[bot]

@petriheino try decreasing your extruder M566 significantly.

Pressure advance works with E jerk (m566, instantaneous speed change). If your E jerk is set way too high, your stepper motor might be acting funny.

Try M566 E240, or even 120.

[petriheino]

@bot
Previous post done with M566:
Maximum jerk rates (mm/min): X: 300.0, Y: 300.0, Z: 600.0, E: 3000.0, jerk policy: 1. It resulted in 699 retraction steps and 656 un-retraction steps

I went ahead and re-captured with M566 E120 but it seems to make the problem worse, by resulting in 713 retraction steps, making problem worse (not affecting un-retraction.) Signal seems same, and motor sound is same (one 2A motor stand-alone on table)

[petriheino]

@bot
By disabling Pressure Advance, retract and un-retract steps are matching, 662 and 662.