[phpBB Debug] PHP Warning: in file [ROOT]/ext/kinerity/bestanswer/event/main_listener.php on line 514: Undefined array key "poster_answers"
The Industrial Raspberry Pi Forum • Delay on DIO output when enabling AIO input
Page 1 of 1

Delay on DIO output when enabling AIO input

Posted: 28 Sep 2021, 11:40
by bpfel
Hi :)

I am using a RevolutionPi Core 3+ connected to a DIO and two AIOs.

The flow I am running is attached below.

What I am trying to accomplish is the following:
1. Read input from AIO/DIO at a regular rate >1Hz. I did that with single revpi-input nodes and a trigger before but figured that might be slower than doing it with a multiple-input node?
2. Use AIO and DIO outputs without delay.

I am encountering the following Problems:
1. Enabling the input node leads to a variable delay on the output pins. Sometimes it takes up to 10s to actually switch the output even if done directly in the editor instead of on the dashboard.
2. Disabling the input node allows me to switch the output pins almost instantaneously as expected.
3. When running node-red in a terminal I can see that there are frequent server disconnects:

Code: Select all

info Authorized by server!
Lost connection to WS Server!
Try to reconnect - Attempt: 1
Connecting to WS Server wss://localhost:8000
Connection to WS Server established!
4. Maybe connected to 3. I have frequent disconnects of the input node which last about 6s.
5. General question: How can I control the sampling rate of the input devices? I see only the option to configure the ADC rate on Pictory.


Code: Select all

[
    {
        "id": "701ef82f416435d4",
        "type": "tab",
        "label": "Sensors",
        "disabled": false,
        "info": ""
    },
    {
        "id": "3940d95f0249304a",
        "type": "group",
        "z": "701ef82f416435d4",
        "name": "Sensors",
        "style": {
            "label": true
        },
        "nodes": [
            "2aa6063af7349cb8",
            "9009daed8236eeb2",
            "0797f9a896b27bc3"
        ],
        "x": 154,
        "y": 479,
        "w": 712,
        "h": 82
    },
    {
        "id": "8d4b290eef1fbf1c",
        "type": "group",
        "z": "701ef82f416435d4",
        "name": "Actuators",
        "style": {
            "fill-opacity": "0.29",
            "label": true
        },
        "nodes": [
            "a5e93056594f52cb",
            "4c8e8a27518d36b5",
            "04581eb5a4098995",
            "01087c136fe2c802",
            "1f1dbc194ea9767f",
            "5ea347eca72d7266",
            "daf5481640d79b49",
            "6bb82af59d0809d2",
            "40ae8bf99dc6d143",
            "487219a026865984",
            "4eeef8e3e594ce2c",
            "4411b719bab4b977",
            "9b295d9e25d0028e"
        ],
        "x": 154,
        "y": 59,
        "w": 572,
        "h": 382
    },
    {
        "id": "93378114576a2377",
        "type": "link out",
        "z": "701ef82f416435d4",
        "name": "Temperature Sensor 1",
        "links": [
            "4a0e1bb1864dbaa9",
            "ab84d58620d4a833"
        ],
        "x": 1235,
        "y": 60,
        "wires": []
    },
    {
        "id": "2aa6063af7349cb8",
        "type": "revpi-multiple-input",
        "z": "701ef82f416435d4",
        "g": "3940d95f0249304a",
        "server": "337fb85cd95e8911",
        "inputPinList": "I_1_i05 InputValue_1 InputValue_1_i04 InputValue_2 InputValue_2_i04 InputValue_3 InputValue_3_i04 InputValue_4_i04 RTDValue_1",
        "inputpin": "I_1_i05 InputValue_1 InputValue_1_i04 InputValue_2 InputValue_2_i04 InputValue_3 InputValue_3_i04 InputValue_4_i04 RTDValue_1",
        "x": 350,
        "y": 520,
        "wires": [
            [
                "9009daed8236eeb2"
            ]
        ]
    },
    {
        "id": "9009daed8236eeb2",
        "type": "function",
        "z": "701ef82f416435d4",
        "g": "3940d95f0249304a",
        "name": "conversion to SI",
        "func": "// conversion of JUMO 00718766\nfunction conv_jumo_temperature(raw){\n    return (raw-4000)/16000.0*170-20;\n} \n// conversion of ifm SV4050\nfunction conv_ifm_flow(raw){\n    return (raw-4000)/1000*0.938;\n}\n// conversion of trafag 8252.78.2517.01.0000.0000.19.34\nfunction conv_trafag_pressure(raw){\n    return (raw-4000)/16000*10+0;\n}\ndata = msg.payload;\nvar measured_values = {}\nmeasured_values.T_KW_ein = data.RTDValue_1;\nmeasured_values.T_Vorlauf = conv_jumo_temperature(data.InputValue_1)\nmeasured_values.T_Reaktor = conv_jumo_temperature(data.InputValue_2);\nmeasured_values.T_Ruecklauf = conv_jumo_temperature(data.InputValue_3);\nmeasured_values.F_Vortex = conv_ifm_flow(data.InputValue_1_i04);\nmeasured_values.Druck = conv_trafag_pressure(data.InputValue_2_i04);\nmeasured_values.F_Coriolis = data.InputValue_3_i04;\nmeasured_values.Rho_Coriolis = data.InputValue_4_i04;\nmeasured_values.Niveau = data.I_1_i05;\n\nreturn measured_values;",
        "outputs": 1,
        "noerr": 0,
        "initialize": "",
        "finalize": "",
        "libs": [],
        "x": 620,
        "y": 520,
        "wires": [
            [
                "0797f9a896b27bc3"
            ]
        ]
    },
    {
        "id": "a5e93056594f52cb",
        "type": "ui_switch",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Pump 2",
        "label": "Pump 2",
        "tooltip": "",
        "group": "76c4ae8cdf5d4854",
        "order": 2,
        "width": 0,
        "height": 0,
        "passthru": true,
        "decouple": "false",
        "topic": "topic",
        "topicType": "msg",
        "style": "",
        "onvalue": "true",
        "onvalueType": "bool",
        "onicon": "",
        "oncolor": "",
        "offvalue": "false",
        "offvalueType": "bool",
        "officon": "",
        "offcolor": "",
        "animate": false,
        "x": 280,
        "y": 160,
        "wires": [
            [
                "4c8e8a27518d36b5"
            ]
        ]
    },
    {
        "id": "4c8e8a27518d36b5",
        "type": "revpi-output",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "server": "337fb85cd95e8911",
        "outputpin": "O_2",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 640,
        "y": 160,
        "wires": []
    },
    {
        "id": "04581eb5a4098995",
        "type": "ui_slider",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Kugelventil2_2",
        "label": "Kugelventil2_2",
        "tooltip": "",
        "group": "76c4ae8cdf5d4854",
        "order": 3,
        "width": 0,
        "height": 0,
        "passthru": true,
        "outs": "end",
        "topic": "topic",
        "topicType": "msg",
        "min": 0,
        "max": "100",
        "step": 1,
        "x": 260,
        "y": 280,
        "wires": [
            [
                "daf5481640d79b49"
            ]
        ]
    },
    {
        "id": "01087c136fe2c802",
        "type": "ui_switch",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Pump 1",
        "label": "Pump 1",
        "tooltip": "",
        "group": "76c4ae8cdf5d4854",
        "order": 1,
        "width": 0,
        "height": 0,
        "passthru": true,
        "decouple": "false",
        "topic": "topic",
        "topicType": "msg",
        "style": "",
        "onvalue": "true",
        "onvalueType": "bool",
        "onicon": "",
        "oncolor": "",
        "offvalue": "false",
        "offvalueType": "bool",
        "officon": "",
        "offcolor": "",
        "animate": false,
        "x": 280,
        "y": 100,
        "wires": [
            [
                "1f1dbc194ea9767f"
            ]
        ]
    },
    {
        "id": "1f1dbc194ea9767f",
        "type": "revpi-output",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "server": "337fb85cd95e8911",
        "outputpin": "O_1",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 640,
        "y": 100,
        "wires": []
    },
    {
        "id": "5ea347eca72d7266",
        "type": "revpi-output",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "server": "337fb85cd95e8911",
        "outputpin": "OutputValue_1",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 610,
        "y": 280,
        "wires": []
    },
    {
        "id": "daf5481640d79b49",
        "type": "function",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "",
        "func": "msg.payload = msg.payload/100.0*32767.0\nreturn msg;",
        "outputs": 1,
        "noerr": 0,
        "initialize": "",
        "finalize": "",
        "libs": [],
        "x": 440,
        "y": 280,
        "wires": [
            [
                "5ea347eca72d7266"
            ]
        ]
    },
    {
        "id": "6bb82af59d0809d2",
        "type": "ui_switch",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Pump 3",
        "label": "Pump 3",
        "tooltip": "",
        "group": "76c4ae8cdf5d4854",
        "order": 2,
        "width": 0,
        "height": 0,
        "passthru": true,
        "decouple": "false",
        "topic": "topic",
        "topicType": "msg",
        "style": "",
        "onvalue": "true",
        "onvalueType": "bool",
        "onicon": "",
        "oncolor": "",
        "offvalue": "false",
        "offvalueType": "bool",
        "officon": "",
        "offcolor": "",
        "animate": false,
        "x": 280,
        "y": 220,
        "wires": [
            [
                "9b295d9e25d0028e"
            ]
        ]
    },
    {
        "id": "40ae8bf99dc6d143",
        "type": "ui_slider",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Umwälzpumpe",
        "label": "Umwälzpumpe",
        "tooltip": "",
        "group": "76c4ae8cdf5d4854",
        "order": 3,
        "width": 0,
        "height": 0,
        "passthru": true,
        "outs": "end",
        "topic": "topic",
        "topicType": "msg",
        "min": 0,
        "max": "100",
        "step": 1,
        "x": 260,
        "y": 340,
        "wires": [
            []
        ]
    },
    {
        "id": "487219a026865984",
        "type": "ui_slider",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Peltier",
        "label": "Peltier",
        "tooltip": "",
        "group": "76c4ae8cdf5d4854",
        "order": 3,
        "width": 0,
        "height": 0,
        "passthru": true,
        "outs": "end",
        "topic": "topic",
        "topicType": "msg",
        "min": 0,
        "max": "100",
        "step": 1,
        "x": 290,
        "y": 400,
        "wires": [
            []
        ]
    },
    {
        "id": "4eeef8e3e594ce2c",
        "type": "revpi-output",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "server": "337fb85cd95e8911",
        "outputpin": "OutputValue_2_i04",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 600,
        "y": 340,
        "wires": []
    },
    {
        "id": "4411b719bab4b977",
        "type": "revpi-output",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "server": "337fb85cd95e8911",
        "outputpin": "OutputValue_1_i04",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 600,
        "y": 400,
        "wires": []
    },
    {
        "id": "9b295d9e25d0028e",
        "type": "revpi-output",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "server": "337fb85cd95e8911",
        "outputpin": "O_3",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 640,
        "y": 220,
        "wires": []
    },
    {
        "id": "0797f9a896b27bc3",
        "type": "debug",
        "z": "701ef82f416435d4",
        "g": "3940d95f0249304a",
        "name": "",
        "active": true,
        "tosidebar": true,
        "console": false,
        "tostatus": false,
        "complete": "true",
        "targetType": "full",
        "statusVal": "",
        "statusType": "auto",
        "x": 770,
        "y": 520,
        "wires": []
    },
    {
        "id": "337fb85cd95e8911",
        "type": "revpi-server",
        "host": "localhost",
        "port": "8000",
        "user": "pi",
        "password": "bphom9",
        "rejectUnauthorized": false,
        "ca": ""
    },
    {
        "id": "76c4ae8cdf5d4854",
        "type": "ui_group",
        "name": "Actuators",
        "tab": "a29a2667a39beed3",
        "order": 1,
        "disp": true,
        "width": "6",
        "collapse": false
    },
    {
        "id": "a29a2667a39beed3",
        "type": "ui_tab",
        "name": "Diagnostic View",
        "icon": "fa-code",
        "order": 2,
        "disabled": false,
        "hidden": false
    }
]

EDIT: Delay on DIO output when enabling AIO input

Posted: 29 Sep 2021, 11:20
by bpfel
I have a workaround using a custom 'exec' node using piTest to set the output pins.

For now this works. Is there a reason not to hook up 20 of those and sending them payload at a high rate? Or rather what am I missing when not using the 'node-red-contrib-revpi-nodes'?

Code: Select all

[
    {
        "id": "edf097c809587d37",
        "type": "subflow",
        "name": "revpi_output ",
        "info": "",
        "category": "Revolution Pi",
        "in": [
            {
                "x": 40,
                "y": 40,
                "wires": [
                    {
                        "id": "459aa0783d491458"
                    }
                ]
            }
        ],
        "out": [],
        "env": [
            {
                "name": "output",
                "type": "str",
                "value": "O_1"
            }
        ],
        "meta": {},
        "color": "#F3B567",
        "icon": "font-awesome/fa-sign-out"
    },
    {
        "id": "459aa0783d491458",
        "type": "function",
        "z": "edf097c809587d37",
        "name": "exec",
        "func": "// convert payload to number in case it is boolean\nmsg.payload = + msg.payload;\n\ncommand = \"piTest -w\" + env.get(\"output\") + \",\" + msg.payload;\nmsg.out = childProcess.execSync(command, { encoding: 'utf-8'});\nreturn msg;",
        "outputs": 1,
        "noerr": 0,
        "initialize": "",
        "finalize": "",
        "libs": [
            {
                "var": "childProcess",
                "module": "child_process"
            }
        ],
        "x": 150,
        "y": 40,
        "wires": [
            []
        ]
    },
    {
        "id": "1ac9818994c727d9",
        "type": "subflow:edf097c809587d37",
        "z": "701ef82f416435d4",
        "g": "8d4b290eef1fbf1c",
        "name": "Pin: O_1",
        "env": [],
        "x": 680,
        "y": 60,
        "wires": []
    }
]

Re: Delay on DIO output when enabling AIO input

Posted: 04 Oct 2021, 12:15
by ->Johannes<-
Hi bpfel,

i moved your topic to "3rd party software --> RevPi Nodes for Node-Red", because it is a Node-Red topic.
The people at Node-RED can probably help you better here.

Nevertheless, we have a small Node-RED FAQ, check it out at
Node-RED FAQ
and search after:

"I notice latencies of 5 seconds between action and reaction. However, when I use piTest everything works in real time - what can I do?"

Here is a videotutorial about Node-RED
Tutorial 26 – Node-RED on RevPi – Part I

Regards
Johannes

Re: Delay on DIO output when enabling AIO input

Posted: 06 Oct 2021, 16:40
by bpfel
Hi Johannes,

thank you for your reply.
I had already found the answer you have linked and reducing the number of flows or splitting input and output to different flows did not solve my problem.
I have also tried to reach the people working on the node-red-revpi nodes but that repository has been inactive for months...

My last hope before resorting to B&R is to use piTest or the underlying code to simply read input.
Do you think that way it would be possible to read ~12 different inputs at a 1Hz rate? Could you help me with that?

Best,

Gianni

Re: Delay on DIO output when enabling AIO input

Posted: 06 Oct 2021, 16:44
by nicolaiB
Hi Gianni,

could you please share the image version of your RevPi and the version of the installed revpi nodes? Also the kernel logfile (/var/log/kern.log or dmesg) and revpi node logfile could be helpful in order to find the root cause of the delay. Do you use any other software on the RevPi which is interacting with the process image?

BR Nicolai

Re: Delay on DIO output when enabling AIO input

Posted: 07 Oct 2021, 10:08
by bpfel
Hi Nicolai,

thanks for your quick response!

I actually just discovered (RTFM) that the workaround via piTest is also valid for reading input by using the -1 flag... Stumbled over the cyclic reading before.
This solves my problem acceptably.

If you would still look into why the revpi-nodes don't seem to work here is the requested info:

Image: Raspbian GNU/Linux 10 (buster)
Revpi Nodes: node-red-contrib-revpi-nodes 1.0.7-2

Minimal flow example, which reproduces both issues:
- WS server looses connection which leads to about 6 seconds of lost measurements on the revpi-input node. (Visible in node-red-log)
- Variable delay on DIO output.

Code: Select all

[
    {
        "id": "ee302bc8cec078f2",
        "type": "tab",
        "label": "Flow 1",
        "disabled": false,
        "info": ""
    },
    {
        "id": "3add1277a4fbdf4a",
        "type": "revpi-multiple-input",
        "z": "ee302bc8cec078f2",
        "server": "fb03780846c8b571",
        "inputPinList": "I_1_i05 InputValue_1 InputValue_1_i04 InputValue_2 InputValue_2_i04 InputValue_3 InputValue_3_i04 InputValue_4 InputValue_4_i04 RTDValue_1",
        "inputpin": "I_1_i05 InputValue_1 InputValue_1_i04 InputValue_2 InputValue_2_i04 InputValue_3 InputValue_3_i04 InputValue_4 InputValue_4_i04 RTDValue_1",
        "x": 240,
        "y": 180,
        "wires": [
            []
        ]
    },
    {
        "id": "fe7fa75f3d884127",
        "type": "revpi-output",
        "z": "ee302bc8cec078f2",
        "server": "fb03780846c8b571",
        "outputpin": "O_2",
        "overwritevalue": false,
        "outputvalue": "",
        "x": 300,
        "y": 280,
        "wires": []
    },
    {
        "id": "c879837e52b00823",
        "type": "inject",
        "z": "ee302bc8cec078f2",
        "name": "",
        "props": [
            {
                "p": "payload"
            },
            {
                "p": "topic",
                "vt": "str"
            }
        ],
        "repeat": "",
        "crontab": "",
        "once": false,
        "onceDelay": 0.1,
        "topic": "",
        "payload": "",
        "payloadType": "date",
        "x": 140,
        "y": 280,
        "wires": [
            [
                "fe7fa75f3d884127"
            ]
        ]
    },
    {
        "id": "fb03780846c8b571",
        "type": "revpi-server",
        "host": "localhost",
        "port": "8000",
        "user": "",
        "password": "",
        "rejectUnauthorized": false,
        "ca": ""
    }
]
node-red-log:

Code: Select all

7 Oct 09:57:47 - [info]
Welcome to Node-RED
===================
7 Oct 09:57:47 - [info] Node-RED version: v2.0.6
7 Oct 09:57:47 - [info] Node.js  version: v14.17.6
7 Oct 09:57:47 - [info] Linux 4.19.95-rt38-v7 arm LE
7 Oct 09:57:48 - [info] Loading palette nodes
7 Oct 09:57:56 - [info] Dashboard version 3.0.4 started at /ui
7 Oct 09:57:57 - [info] Settings file  : /home/pi/.node-red/settings.js
7 Oct 09:57:57 - [info] Context store  : 'default' [module=memory]
7 Oct 09:57:57 - [info] User directory : /home/pi/.node-red
7 Oct 09:57:57 - [info] Projects directory: /home/pi/.node-red/projects
7 Oct 09:57:57 - [info] Server now running at http://127.0.0.1:1880/
7 Oct 09:57:57 - [info] Active project : test_IO
7 Oct 09:57:57 - [info] Flows file     : /home/pi/.node-red/projects/test_IO/flow.json
7 Oct 09:57:57 - [info] Starting flows
Connecting to WS Server wss://localhost:8000
7 Oct 09:57:57 - [info] Started flows
Connection to WS Server established!
info Authorized by server!
Lost connection to WS Server!
Try to reconnect - Attempt: 1
Connecting to WS Server wss://localhost:8000
Connection to WS Server established!
info Authorized by server!
dmesg:

Code: Select all

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.19.95-rt38-v7 (admin@kunbus.de) (gcc version 8.3.0 (Debian 8.3.0-2)) #1 SMP PREEMPT RT Tue, 22 Jun 2021 14:13:31 +0000
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi Compute Module 3 Plus Rev 1.0
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x3ac00000
[    0.000000] On node 0 totalpages: 242688
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:63
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x4e4 with crng_init=0
[    0.000000] percpu: Embedded 17 pages/cpu s39200 r8192 d22240 u69632
[    0.000000] pcpu-alloc: s39200 r8192 d22240 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: coherent_pool=4M bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 smsc95xx.macaddr=B8:27:EB:88:F3:86 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait nosplash plymouth.ignore-serial-consoles
[    0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 938408K/970752K available (8192K kernel code, 661K rwdata, 2292K rodata, 1024K init, 957K bss, 24152K reserved, 8192K cma-reserved)
[    0.000000] Virtual kernel memory layout:
                   vector  : 0xffff0000 - 0xffff1000   (   4 kB)
                   fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
                   vmalloc : 0xbb800000 - 0xff800000   (1088 MB)
                   lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)
                   modules : 0x7f000000 - 0x80000000   (  16 MB)
                     .text : 0x(ptrval) - 0x(ptrval)   (9184 kB)
                     .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
                     .data : 0x(ptrval) - 0x(ptrval)   ( 662 kB)
                      .bss : 0x(ptrval) - 0x(ptrval)   ( 958 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 27600 entries in 81 pages
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu:     RCU priority boosting: priority 1 delay 500 ms.
[    0.000000]  No expedited grace period (rcu_normal_after_boot).
[    0.000000]  Tasks RCU enabled.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000007] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000017] Switching to timer-based delay loop, resolution 52ns
[    0.000269] Console: colour dummy device 80x30
[    0.001384] console [tty1] enabled
[    0.001420] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.001433] pid_max: default: 32768 minimum: 301
[    0.001626] Security Framework initialized
[    0.001633] Yama: becoming mindful.
[    0.001874] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001887] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.002966] CPU: Testing write buffer coherency: ok
[    0.003498] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.060106] Setting up static identity map for 0x100000 - 0x100060
[    0.100090] rcu: Hierarchical SRCU implementation.
[    0.180244] smp: Bringing up secondary CPUs ...
[    0.320896] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.461094] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.601319] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.601639] smp: Brought up 1 node, 4 CPUs
[    0.601758] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.601793] CPU: All CPU(s) started in HYP mode.
[    0.601822] CPU: Virtualization extensions available.
[    0.603120] devtmpfs: initialized
[    0.631245] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.631883] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.631950] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.632669] pinctrl core: initialized pinctrl subsystem
[    0.634334] NET: Registered protocol family 16
[    0.639666] DMA: preallocated 4096 KiB pool for atomic coherent allocations
[    0.649751] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.649800] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.650056] Serial: AMBA PL011 UART driver
[    0.653646] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.714068] bcm2835-dma 3f007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
[    0.716658] SCSI subsystem initialized
[    0.717084] usbcore: registered new interface driver usbfs
[    0.717210] usbcore: registered new interface driver hub
[    0.717392] usbcore: registered new device driver usb
[    0.731389] raspberrypi-firmware soc:firmware: Attached to firmware from 2021-08-31 14:55, variant start
[    0.741317] raspberrypi-firmware soc:firmware: Firmware hash is 67615e950e1e28b92dfae6303cf7a8b879a8908f
[    0.753922] clocksource: Switched to clocksource arch_sys_counter
[    0.925399] VFS: Disk quotas dquot_6.6.0
[    0.925568] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.926157] FS-Cache: Loaded
[    0.926527] CacheFiles: Loaded
[    0.943241] NET: Registered protocol family 2
[    0.944658] tcp_listen_portaddr_hash hash table entries: 512 (order: 2, 16384 bytes)
[    0.944768] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.944943] TCP bind hash table entries: 8192 (order: 5, 229376 bytes)
[    0.945573] TCP: Hash tables configured (established 8192 bind 8192)
[    0.945853] UDP hash table entries: 512 (order: 3, 32768 bytes)
[    0.945992] UDP-Lite hash table entries: 512 (order: 3, 32768 bytes)
[    0.946566] NET: Registered protocol family 1
[    0.947484] RPC: Registered named UNIX socket transport module.
[    0.947523] RPC: Registered udp transport module.
[    0.947554] RPC: Registered tcp transport module.
[    0.947585] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.949862] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.957352] Initialise system trusted keyrings
[    0.957703] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.976458] FS-Cache: Netfs 'nfs' registered for caching
[    0.987689] NFS: Registering the id_resolver key type
[    0.987761] Key type id_resolver registered
[    0.987794] Key type id_legacy registered
[    0.987846] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.991747] Key type asymmetric registered
[    0.991790] Asymmetric key parser 'x509' registered
[    0.991892] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
[    0.992149] io scheduler noop registered
[    0.992185] io scheduler deadline registered (default)
[    0.992716] io scheduler cfq registered
[    0.992751] io scheduler mq-deadline registered (default)
[    0.992787] io scheduler kyber registered
[    1.000682] bcm2708_fb soc:fb: FB found 1 display(s)
[    1.011166] Console: switching to colour frame buffer device 80x30
[    1.019097] bcm2708_fb soc:fb: Registered framebuffer for display 0, size 640x480
[    1.026379] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    1.031786] bcm2835-rng 3f104000.rng: hwrng registered
[    1.035322] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.042003] vc-sm: Videocore shared memory driver
[    1.045585] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    1.072040] brd: module loaded
[    1.096925] loop: module loaded
[    1.100821] Loading iSCSI transport class v2.0-870.
[    1.104908] libphy: Fixed MDIO Bus: probed
[    1.107997] usbcore: registered new interface driver lan78xx
[    1.111033] usbcore: registered new interface driver smsc95xx
[    1.114075] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.644928] dwc_otg 3f980000.usb: base=(ptrval)
[    1.847949] Core Release: 2.80a
[    1.850685] Setting default values for core params
[    1.853499] Finished setting default values for core params
[    2.057023] Using Buffer DMA mode
[    2.059861] Periodic Transfer Interrupt Enhancement - disabled
[    2.062799] Multiprocessor Interrupt Enhancement - disabled
[    2.065811] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.068716] Dedicated Tx FIFOs mode
[    2.072154] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = bb004000 dma = 0xfb004000 len=9024
[    2.077987] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    2.091411] dwc_otg: Microframe scheduler enabled
[    2.091471] WARN::hcd_init_fiq:457: FIQ on core 1
[    2.091479] WARN::hcd_init_fiq:458: FIQ ASM at 806b450c length 36
[    2.091488] WARN::hcd_init_fiq:497: MPHI regs_base at bb810000
[    2.091504] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.101807] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.107221] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    2.110001] Init: Port Power? op_state=1
[    2.112689] Init: Power Port (0)
[    2.115747] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    2.121210] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.126925] usb usb1: Product: DWC OTG Controller
[    2.129798] usb usb1: Manufacturer: Linux 4.19.95-rt38-v7 dwc_otg_hcd
[    2.132707] usb usb1: SerialNumber: 3f980000.usb
[    2.136772] hub 1-0:1.0: USB hub found
[    2.139668] hub 1-0:1.0: 1 port detected
[    2.143395] dwc_otg: FIQ enabled
[    2.143405] dwc_otg: NAK holdoff enabled
[    2.143413] dwc_otg: FIQ split-transaction FSM enabled
[    2.143432] Module dwc_common_port init
[    2.144345] usbcore: registered new interface driver usb-storage
[    2.147449] mousedev: PS/2 mouse device common for all mice
[    2.152662] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.155911] bcm2835-cpufreq: min=600000 max=1200000
[    2.161180] sdhci: Secure Digital Host Controller Interface driver
[    2.162652] sdhci: Copyright(c) Pierre Ossman
[    2.164585] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    2.166257] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.168569] hidraw: raw HID events driver (C) Jiri Kosina
[    2.170229] usbcore: registered new interface driver usbhid
[    2.171758] usbhid: USB HID core driver
[    2.173812] vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
[    2.176568] [vc_sm_connected_init]: start
[    2.183694] [vc_sm_connected_init]: end - returning 0
[    2.186259] Initializing XFRM netlink socket
[    2.187784] NET: Registered protocol family 17
[    2.189360] Key type dns_resolver registered
[    2.191061] Registering SWP/SWPB emulation handler
[    2.193083] registered taskstats version 1
[    2.194501] Loading compiled-in X.509 certificates
[    2.204758] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    2.212123] rtc-pcf2127-i2c 1-0051: rtc core: registered rtc-pcf2127-i2c as rtc0
[    2.217478] rtc-pcf2127-i2c 1-0051: setting system clock to 2021-10-07 07:57:31 UTC (1633593451)
[    2.354007] Indeed it is in host mode hprt0 = 00021501
[    2.428328] random: fast init done
[    2.563942] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.565780] Indeed it is in host mode hprt0 = 00001101
[    2.804212] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
[    2.807307] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.809482] hub 1-1:1.0: USB hub found
[    2.811160] hub 1-1:1.0: 5 ports detected
[    3.021060] sdhost: log_buf @ (ptrval) (fb007000)
[    3.027720] random: crng init done
[    3.071208] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    3.075024] of_cfs_init
[    3.076669] of_cfs_init: OK
[    3.078786] Waiting for root device /dev/mmcblk0p2...
[    3.143952] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.149687] mmc0: new high speed MMC card at address 0001
[    3.152170] mmcblk0: mmc0:0001 BJTD4R 29.1 GiB
[    3.154555] mmcblk0boot0: mmc0:0001 BJTD4R partition 1 4.00 MiB
[    3.156829] mmcblk0boot1: mmc0:0001 BJTD4R partition 2 4.00 MiB
[    3.158628] mmcblk0rpmb: mmc0:0001 BJTD4R partition 3 4.00 MiB, chardev (246:0)
[    3.172883]  mmcblk0: p1 p2
[    3.204598] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.207524] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.209664] devtmpfs: mounted
[    3.214882] Freeing unused kernel memory: 1024K
[    3.216531] Run /sbin/init as init process
[    3.274283] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[    3.277150] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.282697] smsc95xx v1.0.6
[    3.378011] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, c8:3e:a7:01:c6:f1
[    3.910590] NET: Registered protocol family 10
[    3.913296] Segment Routing with IPv6
[    3.939022] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    3.946445] systemd[1]: Detected architecture arm.
[    3.959337] systemd[1]: Set hostname to <RevPi50205>.
[    4.628522] systemd[1]: Listening on udev Control Socket.
[    4.637176] systemd[1]: Created slice system-getty.slice.
[    4.641366] systemd[1]: Listening on Syslog Socket.
[    4.645744] systemd[1]: Listening on Journal Socket.
[    4.656134] systemd[1]: Starting Load Kernel Modules...
[    4.660384] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    4.664375] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
[    4.718206] i2c /dev entries driver
[    4.855285] ks8851 spi0.1: spi0.1 supply vdd-io not found, using dummy regulator
[    4.855422] ks8851 spi0.1: Linked as a consumer to regulator.0
[    4.855562] ks8851 spi0.1: Dropping the link to regulator.0
[    4.855911] ks8851 spi0.0: spi0.0 supply vdd-io not found, using dummy regulator
[    4.856018] ks8851 spi0.0: Linked as a consumer to regulator.0
[    4.856141] ks8851 spi0.0: Dropping the link to regulator.0
[    4.857021] ks8851 spi0.1: spi0.1 supply vdd-io not found, using dummy regulator
[    4.857115] ks8851 spi0.1: Linked as a consumer to regulator.0
[    4.857257] ks8851 spi0.1: Dropping the link to regulator.0
[    4.857363] ks8851 spi0.0: spi0.0 supply vdd-io not found, using dummy regulator
[    4.857469] ks8851 spi0.0: Linked as a consumer to regulator.0
[    4.857592] ks8851 spi0.0: Dropping the link to regulator.0
[    4.905269] ks8851 spi0.1: spi0.1 supply vdd-io not found, using dummy regulator
[    4.908827] ks8851 spi0.1: Linked as a consumer to regulator.0
[    4.910679] ks8851 spi0.1: Linked as a consumer to regulator.1
[    5.014029] ks8851 spi0.1: message enable is 0
[    5.019172] ks8851 spi0.1 pieth0: revision 1, MAC 56:02:04:43:17:2e, IRQ 0 (polling), no EEPROM
[    5.022563] ks8851 spi0.0: spi0.0 supply vdd-io not found, using dummy regulator
[    5.026206] ks8851 spi0.0: Linked as a consumer to regulator.0
[    5.033746] ks8851 spi0.0: Linked as a consumer to regulator.1
[    5.046554] ks8851 spi0.0: message enable is 0
[    5.051762] ks8851 spi0.0 pieth1: revision 1, MAC fa:52:71:0b:7d:55, IRQ 0 (polling), no EEPROM
[    5.106160] piControl: loading out-of-tree module taints kernel.
[    5.121809] piControl: built: Tue Jun 22 14:17:19 UTC 2021
[    5.123466] piControl: RevPi Core
[    5.125150] piControl: MAJOR-No.  : 241
[    5.127087] piControl: MAJOR-No.  : 241  MINOR-No.  : 0
[    5.160391] piControl: read file finished, f_pos=14714
[    5.162096] piControl: 4 devices found
[    5.163575] piControl: 209 entries in total
[    5.168300] piControl: cl-comp:  0 addr  6  bit ff  len   8
[    5.169793] piControl: cl-comp:  1 addr 81  bit ff  len   8
[    5.171227] piControl: cl-comp:  2 addr 82  bit ff  len   8
[    5.184659] uart-pl011 3f201000.serial: no DMA platform data
[    5.184735] piControl: filp_open -1206473472
[    5.184780] piControl: set priority of spi0 to 54
[    5.187595] piControl: piIO thread started
[    5.187603] piControl: RevPiDevice_init()
[    5.187609] piControl: Enter Init State
[    5.187738] piControl: PADS 0 = 0x1b   slew=1  hyst=1  drive=3
[    5.187743] piControl: PADS 1 = 0x1b   slew=1  hyst=1  drive=3
[    5.187748] piControl: PADS 2 = 0x1b   slew=1  hyst=1  drive=3
[    5.187766] piControl: piControlInit done
[    5.188266] piControl: Enter PresentSignalling1 State
[    5.227457] piControl: Enter InitialSlaveDetectionRight State
[    5.227996] piControl: Enter ConfigRightStart State
[    5.238788] piControl: Enter ConfigDialogueRight State
[    5.274013] piControl: GetDeviceInfo: Id 96
[    5.304035] piControl: found 2. device on right side. Moduletype 96. Designated address 32
[    5.304046] piControl: input offset     11  len  70
[    5.304051] piControl: output offset    81  len  18
[    5.304595] piControl: Enter SlaveDetectionRight State
[    5.314539] piControl: Enter ConfigDialogueRight State
[    5.337028] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    5.344048] piControl: GetDeviceInfo: Id 103
[    5.374048] piControl: found 3. device on right side. Moduletype 103. Designated address 33
[    5.374056] piControl: input offset     99  len  20
[    5.374060] piControl: output offset   119  len   4
[    5.374614] piControl: Enter SlaveDetectionRight State
[    5.384545] piControl: Enter ConfigDialogueRight State
[    5.414056] piControl: GetDeviceInfo: Id 103
[    5.414653] systemd-journald[131]: Received request to flush runtime journal from PID 1
[    5.444698] piControl: found 4. device on right side. Moduletype 103. Designated address 34
[    5.444708] piControl: input offset    123  len  20
[    5.444712] piControl: output offset   143  len   4
[    5.445266] piControl: Enter SlaveDetectionRight State
[    5.455758] piControl: Enter InitialSlaveDetectionLeft State
[    5.456297] piControl: Enter EndOfConfig State

[    5.456310] piControl: Device  0: Addr  0 Type  95  Act 1  In   6 Out   5
[    5.456315] piControl:            input offset      0  len   6
[    5.456320] piControl:            output offset     6  len   5
[    5.456325] piControl:            serial number 1  version 1.2
[    5.456335] piControl: Device  1: Addr 32 Type  96  Act 1  In  70 Out  18
[    5.456341] piControl:            input offset     11  len  70
[    5.456345] piControl:            output offset    81  len  18
[    5.456350] piControl:            serial number -1  version 1.5
[    5.456356] piControl: Device  2: Addr 33 Type 103  Act 1  In  20 Out   4
[    5.456361] piControl:            input offset     99  len  20
[    5.456366] piControl:            output offset   119  len   4
[    5.456371] piControl:            serial number 58148  version 1.4
[    5.456377] piControl: Device  3: Addr 34 Type 103  Act 1  In  20 Out   4
[    5.456382] piControl:            input offset    123  len  20
[    5.456387] piControl:            output offset   143  len   4
[    5.456392] piControl:            serial number 58243  version 1.4
[    5.456395] piControl:
[    5.456406] piControl: Adjust: base 0 in 0 out 6 conf 0
[    5.456413] piControl: Adjust: base 11 in 11 out 81 conf 99
[    5.456419] piControl: Adjust: base 124 in 124 out 144 conf 148
[    5.456425] piControl: Adjust: base 213 in 213 out 233 conf 237
[    5.456430] piControl: After Adjustment
[    5.456436] piControl: Device  0: Addr  0 Type  95  Act 1  In   6 Out   5
[    5.456441] piControl:            input offset      0  len   6
[    5.456446] piControl:            output offset     6  len   5
[    5.456453] piControl: Device  1: Addr 32 Type  96  Act 1  In  70 Out  18
[    5.456458] piControl:            input offset     11  len  70
[    5.456463] piControl:            output offset    81  len  18
[    5.456469] piControl: Device  2: Addr 33 Type 103  Act 1  In  20 Out   4
[    5.456474] piControl:            input offset    124  len  20
[    5.456478] piControl:            output offset   144  len   4
[    5.456488] piControl: Device  3: Addr 34 Type 103  Act 1  In  20 Out   4
[    5.456498] piControl:            input offset    213  len  20
[    5.456505] piControl:            output offset   233  len   4
[    5.456509] piControl:
[    5.573992] piControl: start data exchange
[    5.816415] piControl: piDIOComm_Init done 0
[    5.826245] piControl: piAIOComm_Init done 0
[    5.836734] piControl: piAIOComm_Init done 0
[    5.845696] piControl: set BridgeState to running
[    7.242470] ks8851 spi0.1 piright: renamed from pieth0
[    7.355588] ks8851 spi0.0 pileft: renamed from pieth1
[    8.435735] media: Linux media interface: v0.10
[    8.485529] videodev: Linux video capture interface: v2.00
[    8.491896] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    8.498993] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    8.499071] [vc_sm_connected_init]: start
[    8.500801] [vc_sm_connected_init]: installed successfully
[    8.520042] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    8.521405] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    8.528677] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    8.546388] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    8.554259] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    8.554286] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    8.557863] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    8.557887] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    8.562671] : bcm2835_codec_get_supported_fmts: port has more encoding than we provided space for. Some are dropped.
[    8.564344] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    8.564369] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    8.766881] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    8.780608] bcm2835_audio soc:audio: card created with 8 channels
[   11.482817] 8021q: 802.1Q VLAN Support v1.8
[   11.690002] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   11.764286] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   12.167133] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   13.651908] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xC1E1
[   14.735283] warning: process `colord-sane' used the deprecated sysctl system call with 8.1.2.
And no there is no additional software running, at least to my knowledge.

Best and thank you!

Gianni

Re: Delay on DIO output when enabling AIO input

Posted: 08 Oct 2021, 13:53
by nicolaiB
Hi Gianni,

thanks for all the informations. I'll try to reproduce the error with my test setup, but can't promise anything yet. As I understand you last post the solution with piTest works for you - at least for now.

Nicolai