Skip to content

Question: node-driver use to work with a callback in the readTag call. Is this not possible any more? #6

Closed

Description

@gman8a

Justin,

Questions
"node-drivers" use to work with a callback in the read Tag call.
Is this not possible any more?
I am not sure what "await" does. Does the node executive loop process other functions while waiting ?

  Also, can "node-drivers" talk to a A/B Compact-Logix or Control-Logix PLC ?
   If so, I see no examples of this. Seem like all the necessary low level code is in place for this.

Activity

  1. jmmoser commented on Oct 15, 2021

    @jmmoser
    Owner

    Can you share the error you receive when you try to use a callback? You should be able to do something like this without issue:

    logix5000.readTag('tagname', function(res) {
    
    });

    Async/await is syntax for writing asynchronous JavaScript and is built on top of promises. Here are a few links that cover async/await:

    The node executive loop (event loop) is single threaded and will only process one function at a time, however, I/O runs on separate threads. This means you can run one asynchronous function, then run another ansynchronous function, then wait for both of them to finish. See the code example below:

    /**
     * test1 requests the value of tag1 and waits for the response,
     * then requests the value of tag2 and waits for the response
     */
    async function test1() {
    	const promise1 = logix5000.readTag('tag1');
    	const value1 = await promise1;
    
    	const promise2 = logix5000.readTag('tag2');  
    	const value2 = await promise2;
    }
    
    /**
     * test2 requests the value of tag1, then requests the value of tag2,
     * then waits for the response of tag1, then waits for the response of tag2.
     * This may execute faster than test1 because while it is waiting for tag1's response, tag2's
     * value has already been requested.  It doesn't wait for tag1's response before requesting tag1's value.
     */
    async function test2() {
    	  const promise1 = logix5000.readTag('tag1');
    	  const promise2 = logix5000.readTag('tag2');
    	  
    	  const value1 = await promise1;
    	  const value2 = await promise2;
    }

    Use the Logix5000 layer on top of the TCP layer to communicate with Control-Logix and Compact-Logix PLCs. The code example is here. The documentation I followed for developing the Logix5000 layer is here.

  2. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    I figured it out.
    Promises are new to me.

    Here is what I wrote

    ~/wic/plc2$ cat p2.js

    //---------------code---------------------
    const { TCP, CIP } = require('node-drivers');
    const tcpLayer = new TCP('192.168.100.174');

    // with eip layer
    // const eipLayer = new CIP.EIP(tcpLayer);
    // const logix5000 = new CIP.Logix5000(eipLayer);

    // w/o eip layer
    const cipLayer = new CIP(tcpLayer);
    const logix5000 = new CIP.Logix5000(tcpLayer);

    console.log( new Date() )
    logix5000.readTag('HMI_CC03_FULL[0]').then( (result) => {
    console.log(new Date())
    console.log(result);

    }).catch( (error) => {
    	console.log(error);
    

    });
    //----------end code ----------------

    /*---output
    X_Rcv:~/wic/plc2$ node p1.js
    2021-10-15T17:28:50.063Z
    2021-10-15T17:28:50.167Z
    1344

    My comment: Is very slow, taking ~ 104ms
    
    vs. another method:
    

    X_Rcv:~/wic/plc2$ echo "mread,0,hmi_cc03_jam[0]/hmi_cc03_full[0];"|nc localhost 9000

    0:ok/13ms,MREAD,0,DINT:hmi_cc03_jam[0]=0/DINT:hmi_cc03_full[0]=1344;
    ^^
    ## 13ms

    Q: Did you ever test speed of callbacks vs promises ?

    */

  3. jmmoser commented on Oct 15, 2021

    @jmmoser
    Owner

    @gman8a Your second example doesn't test the speed of using callbacks in this package and instead appears to be using using a different program. Can you try running the following code? This code first reads the tag using a promise and then reads the same tag using a callback. This still may not be a fair test because there might be some setup happening for the first read that the second read is able to take advantage of.

    const { TCP, CIP } = require('node-drivers');
    
    const tcpLayer = new TCP('192.168.100.174');
    const logix5000 = new CIP.Logix5000(tcpLayer);
    
    const promiseStart = Date.now();
    logix5000.readTag('HMI_CC03_FULL[0]').then(() => {
    	const promiseEnd = Date.now();
    	console.log('Time elapsed for promise:', promiseEnd - promiseStart);
    
    	const callbackStart = Date.now();
    	logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {
    		const callbackEnd = Date.now();
    		if (err) {
    			console.log('Error reading tag using callback', err);
    		} else {
    			console.log('Time elapsed for callback:', callbackEnd - callbackStart);
    		}
    		
    		tcpLayer.close();
    	});
    }).catch((err) => {
    	console.log('Error reading tag using promise', err);
    	tcpLayer.close();
    });
  4. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    // output of your test program request:

    _Rcv:/wic/plc2$ vim p1.js
    _Rcv:
    /wic/plc2$ node p1.js
    2021-10-15T18:18:10.022Z
    Time elapsed for promise: 76
    Time elapsed for callback: 4
    InfoError: Close
    at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPInternalLayer.js:42:22
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:43
    at Map.forEach ()
    at internalDestroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:29)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:105:7
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at async /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:157:14 {
    info: undefined
    }
    HMI_CC03_FULL[0]
    InfoError: Close
    at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:206:20
    at send (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:1000:5)
    at processTicksAndRejections (internal/process/task_queues.js:93:5) {
    info: undefined
    }

  5. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    So... What is the best code to get minimum overall time from application call to return value into application ?

  6. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    I guess it it this, as programmed in your example to me.

    const callbackStart = Date.now();
    logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {
    const callbackEnd = Date.now();
    if (err) {
    console.log('Error reading tag using promise', err);
    } else {
    console.log('Time elapsed for callback:', callbackEnd - callbackStart);
    }

    	tcpLayer.close();
    });
    
  7. jmmoser commented on Oct 15, 2021

    @jmmoser
    Owner

    Interesting! Try running this as well and let me know the results:

    const { TCP, CIP } = require('node-drivers');
    
    const tcpLayer = new TCP('192.168.100.174');
    const logix5000 = new CIP.Logix5000(tcpLayer);
    
    const callbackStart = Date.now();
    logix5000.readTag('HMI_CC03_FULL[0]', (err, result1) => {
        const callbackEnd = Date.now();
        if (err) {
            console.log('Error reading tag using callback', err);
        } else {
            console.log('Time elapsed for callback:', callbackEnd - callbackStart);
    		console.log(result1);
        }
    
        const promiseStart = Date.now();
        logix5000.readTag('HMI_CC03_FULL[0]').then((result2) => {
            const promiseEnd = Date.now();
            console.log('Time elapsed for promise:', promiseEnd - promiseStart);
    		console.log(result2);
        }).catch((err) => {
            console.log('Error reading tag using promise', err);
        }).finally(() => {
            tcpLayer.close();
        });
    });
  8. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    HMI_CC03_FULL[0]
    cnt: 7 Error reading tag using promise InfoError: connection.cip error: ConnectionFailure, Connection in use or duplicate forward open
    at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:206:20
    at send (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:1000:5)
    at processTicksAndRejections (internal/process/task_queues.js:93:5) {
    info: undefined
    }
    InfoError: connection.cip error: ConnectionFailure, Connection in use or duplicate forward open
    at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPInternalLayer.js:42:22
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:43
    at Map.forEach ()
    at internalDestroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:275:29)
    at Logix5000.destroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:117:5)
    at CIPConnectionLayer.destroy (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/Layer.js:114:23)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPConnectionLayer.js:575:18
    at handleUnconnectedMessage (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPConnectionLayer.js:225:7)
    at CIPConnectionLayer.handleData (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/internal/CIPConnectionLayer.js:143:7) {
    info: undefined
    }
    HMI_CC03_FULL[0]
    cnt: 8 Error reading tag using promise InfoError: connection.cip error: ConnectionFailure, Connection in use or duplicate forward open
    at Object.reject (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/utils.js:131:19)
    at /mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:206:20
    at send (/mnt/WIC/wic_handcraft2/plc2/node_modules/node-drivers/src/layers/cip/layers/Logix5000/index.js:1000:5)
    at processTicksAndRejections (internal/process/task_queues.js:93:5) {
    info: undefined
    }

    ^^^^^^^^^^^^^ERROR FROMP REVIOUS RUN ABOVE ^^^^^^^^^^^

    Rcv:~/wic/plc2$ node p1.js
    here 1
    here 2
    here 3
    here 4
    here 5
    here 6
    here 7
    here 8
    cnt: 2 Time elapsed for callback: 86
    cnt: 3 Time elapsed for callback: 91
    cnt: 4 Time elapsed for callback: 93
    cnt: 5 Time elapsed for callback: 96
    cnt: 6 Time elapsed for callback: 99
    cnt: 7 Time elapsed for callback: 101
    cnt: 8 Time elapsed for callback: 103

    -------------CODE---------------------
    function f1(cnt){
    let callbackStart = Date.now();
    console.log('here ', cnt);

    	logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {
    
    		let callbackEnd = Date.now();
    
    			if (err) {
    					console.log('cnt:', cnt,'  Error reading tag using promise', err);
    			} else {
    					
    					console.log('cnt:', cnt, '  Time elapsed for callback:', callbackEnd - callbackStart);
    			}
    				
    	});
    

    }//fn

    f1(1)
    f1(2);
    f1(3);
    f1(4);
    f1(5);
    f1(6);
    f1(7);
    f1(8);

    setTimeout( ()=>{

    logix5000.close();
    cipLayer.close();
    tcpLayer.close(); 
    
    
    process.exit(); 
    

    }, 3000);

    -----------END CODE------------------------

  9. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    result of your last execution request

    Rcv:~/wic/plc2$ node p3.js
    Time elapsed for callback: 85
    1344
    Time elapsed for promise: 6
    1344

  10. jmmoser commented on Oct 15, 2021

    @jmmoser
    Owner

    Based on the first test and the second test, the speeds of using callbacks and promises are identical. The reason the first read is slow in both tests is the stack has to establish the TCP connection, then the EIP connection, then the CIP connection, and then it executes the CIP read request. The second read uses the existing TCP/EIP/CIP connections and simply executes the read request.

  11. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    ...well in my last test w/ consecutive f1() calls, the elapsed times were around 100ms.
    what up here.

  12. jmmoser commented on Oct 15, 2021

    @jmmoser
    Owner

    In your consecutive f1() test, you aren't really reading the tag 8 times consecutively. You are really queuing 8 requests to read the tag. f1(2) runs before f1(1) finishes hence why you see all of the logs stating here 1 here 2 here 3... first before you see cnt: 1 Time elapsed for callback: ##....

    To make your test read the tags consecutively, do this instead:

    function f1(cnt, cb) {
        let callbackStart = Date.now();
        console.log('here ', cnt);
    
        logix5000.readTag('HMI_CC03_FULL[0]', (err, result) => {
    
            let callbackEnd = Date.now();
    
            if (err) {
                console.log('cnt:', cnt, '  Error reading tag using promise', err);
            } else {
    
                console.log('cnt:', cnt, '  Time elapsed for callback:', callbackEnd - callbackStart);
            }
    
            if (typeof cb === 'function') cb();
        });
    }//fn
    
    /** call f1(1) first */
    f1(1, () => {
        /** call f1(2) after f1(1) finishes */
        f1(2, () => {
            /** call f1(3) after f1(2) finishes */
            f1(3, () => {
                /** etc... */
                f1(4, () => {
                    f1(5, () => {
                        f1(6, () => {
                            f1(7, () => {
                                f1(8);
                            });
                        });
                    });
                });
            });
        });
    });
    
    setTimeout(() => {
    
        logix5000.close();
        cipLayer.close();
        tcpLayer.close();
    
    
        process.exit();
    
    }, 3000);

    I expect you will see the following:

    here 1
    Time elapsed for callback: 75 (approximately)
    here 2
    Time elapsed for callback: 6 (approximately)
    here 3
    Time elapsed for callback: 4 (approximately)
    here 4
    Time elapsed for callback: 5 (approximately)
    ...
    here 8
    Time elapsed for callback: 5 (approximately)
    

    The first request takes the most time because the stack has to establish the connection to the PLC and then all the remaining requests take a short amount of time.

    You should also notice one of the drawbacks of using callbacks in the code above which some people refer to as "callback hell"! With async/await you could rewrite the code above as:

    async function f1(cnt) {
        let callbackStart = Date.now();
        console.log('here ', cnt);
    
        try {
            await logix5000.readTag('HMI_CC03_FULL[0]');
            let callbackEnd = Date.now();
            console.log('cnt:', cnt, '  Time elapsed for callback:', callbackEnd - callbackStart);
        } catch (err) {
            console.log('cnt:', cnt, '  Error reading tag using promise', err);
        }
    }//fn
    
    
    (async () => {
        /** call f1(1) first */
        await f1(1);
        /** call f1(2) after f1(1) finishes */
        await f1(2);
        /** call f1(3) after f1(2) finishes */
        await f1(3);
        /** etc... */
        await f1(4);
        await f1(5);
        await f1(6);
        await f1(7);
        await f1(8);
    })();
    
    setTimeout(() => {
    
        logix5000.close();
        cipLayer.close();
        tcpLayer.close();
    
    
        process.exit();
    
    }, 3000);
  13. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    ///output of your last program request follows

    _Rcv:~/wic/plc2$ node p4.js
    here 1
    cnt: 1 Time elapsed for callback: 99
    here 2
    cnt: 2 Time elapsed for callback: 6
    here 3
    cnt: 3 Time elapsed for callback: 4
    here 4
    cnt: 4 Time elapsed for callback: 4
    here 5
    cnt: 5 Time elapsed for callback: 4
    here 6
    cnt: 6 Time elapsed for callback: 4
    here 7
    cnt: 7 Time elapsed for callback: 4
    here 8
    cnt: 8 Time elapsed for callback: 4

    /plc2/p4.js:49
    cipLayer.close();
    ^

    ReferenceError: cipLayer is not defined
    at Timeout._onTimeout (/mnt/WIC/wic_handcraft2/plc2/p4.js:49:5)
    at listOnTimeout (internal/timers.js:554:17)
    at processTimers (internal/timers.js:497:7)

  14. jmmoser commented on Oct 15, 2021

    @jmmoser
    Owner

    Perfect! Does it make sense now?

  15. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    ...more than it did when i started.

    ..however my application looks like this:
    //////////////////////////
    function readmytag(tagname, (result) => {

              ..
              ..
              ...
             plc_result_data_handler(result);
    
    });
    
    readmytag('HMI_CC03_FULL[0]');
    

    //////////////////////

    The time from the app call to the handler should be 5ms.
    Please code this for me !!

  16. gman8a commented on Oct 15, 2021

    @gman8a
    Author

    correction
    plc_result_data_handler( {tagname:tagname, result:result} );

  17. Repository owner locked and limited conversation to collaborators on Oct 15, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions