Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

peaks in read time when using 0 timeout #419

Open
ronytigo opened this issue Mar 5, 2023 · 15 comments
Open

peaks in read time when using 0 timeout #419

ronytigo opened this issue Mar 5, 2023 · 15 comments
Labels
performance question

Comments

@ronytigo
Copy link

ronytigo commented Mar 5, 2023

This is my code:

    #include <iostream>
    #include <chrono>
    #include <fstream>
    #include <string>
    #include <cstring>
    #include "../lib/libplctag.h"
    #include "utils.h"
    #include <inttypes.h>
    #include <vector>
    #include <thread>
    #include <unistd.h>
    #include <sys/time.h>
    #include <atomic>

    int64_t util_time_ms(void)
    {
        struct timeval tv;
        gettimeofday(&tv, NULL);
        return ((int64_t)tv.tv_sec * 1000) + ((int64_t)tv.tv_usec / 1000);
    }

    int main(int argc, char *argv[])
    {
        std::string m_tag_full_path = "some valid path";
        int64_t start = 0;
        int64_t end = 0;
        int64_t total_ms = 0;
        **int timeout = 0;**
        **int plc_tag = plc_tag_create(m_tag_full_path.c_str(), 1000);**
        while(true)
        {
            start = util_time_ms();
            **int status = plc_tag_read(plc_tag, timeout);**
            **do{
                status = plc_tag_status(plc_tag);
            } while (status == PLCTAG_STATUS_PENDING);**
            **end = util_time_ms();**
            if (status != PLCTAG_STATUS_OK)
            {
                std::cout << "can't read tag " << m_tag_full_path << " - aborting! status is " << status << std::endl;
                plc_tag_abort(plc_tag);
            }

            **total_ms = (end - start);
            std::cout << "read tag in " << total_ms << " ms" << std::endl;**
        }
    }

when timeout is 0, this is the output I get:

read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 100 ms
read tag in 0 ms
read tag in 100 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 200 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 300 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 200 ms
read tag in 0 ms
read tag in 100 ms
read tag in 100 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 100 ms
read tag in 0 ms
read tag in 100 ms
read tag in 100 ms
read tag in 0 ms
read tag in 0 ms
read tag in 100 ms
read tag in 0 ms
read tag in 200 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 201 ms
read tag in 0 ms
read tag in 0 ms
read tag in 100 ms

When the timeout is 10, I get:

read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 1 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
read tag in 0 ms
@timyhac
Copy link

timyhac commented Mar 6, 2023

How confident are you that the measurements are valid? util_time_ms doesn't look right to me.

@kyle-github
Copy link
Member

Based on the code there, you are going to get some strange timeouts, @ronytigo. Your loop checking for the tag status does not give up the CPU at all:

            do{
                status = plc_tag_status(plc_tag);
            } while (status == PLCTAG_STATUS_PENDING);

You need to add a delay with a sleep or somehow signal to the OS that the thread can be rescheduled.

The timeout durations are suspicious, however. The base timeout in the main IO thread is 100ms.

What operating system, compiler and libplctag version are you using?

@ronytigo
Copy link
Author

ronytigo commented Mar 7, 2023

util_time_ms is taken from this repository and it looks ok.
@kyle-github
I added usleep(100) inside the loop, I get similar results.

NAME="Ubuntu"
VERSION="20.04.4 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian

LIBPLC_REQUIRED_VERSION 2, 1, 0

set(CMAKE_CXX_COMPILER_ID "GNU")
set(CMAKE_CXX_COMPILER_VERSION "9.4.0")

@ronytigo
Copy link
Author

ronytigo commented Mar 7, 2023

Also tried on another machine with another plc. same results.

@kyle-github
Copy link
Member

Thanks for trying that. Please try to use a function that forces a thread to yield the CPU, such as sched_yield(): https://man7.org/linux/man-pages/man2/sched_yield.2.html

What version of the library are you using? The requirement macro just tells the library the minimum version of the API needed, not the version of the library to load.

@ronytigo
Copy link
Author

ronytigo commented Mar 7, 2023

Added sched_yield() after the usleep(100), same results.
Sorry, but how do I check the version I'm using?

@kyle-github
Copy link
Member 

    /* output the version we are using. */
    printf("Library version %d.%d.%d.\n",
                            plc_tag_get_int_attribute(0, "version_major", 0),
                            plc_tag_get_int_attribute(0, "version_minor", 0),
                            plc_tag_get_int_attribute(0, "version_patch", 0));

Thanks for trying sched_yield().

@ronytigo
Copy link
Author

ronytigo commented Mar 7, 2023

Thanks!
Library version 2.5.5.

@ronytigo
Copy link
Author

@kyle-github any idea?

@kyle-github
Copy link
Member

Sorry, I've been ill. This is looking like it might be a bug, but I cannot tell what the library is doing during those long delays.

Can you turn on debugging to level 4 and capture the output of the test that shows occasional 100+ms delays?

You can do this by appending "&debug=4" to the tag string or by calling plc_tag_set_debug_level(PLCTAG_DEBUG_DETAIL); in your code before you start calling other library functions.

@ronytigo
Copy link
Author

sure, thanks!

2023-03-16 17:33:30.126 thread(1) tag(11) INFO plc_tag_read:1607 Starting.
2023-03-16 17:33:30.126 thread(1) tag(11) INFO tag_read_start:307 Starting
2023-03-16 17:33:30.126 thread(1) tag(11) INFO build_read_request_connected:418 Starting.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL session_create_request:2517 Starting.
2023-03-16 17:33:30.126 thread(1) tag(11) INFO rc_alloc_impl:111 Starting, called from session_create_request:2526
2023-03-16 17:33:30.126 thread(1) tag(11) INFO rc_alloc_impl:130 Done
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL rc_alloc_impl:135 Returning memory pointer 0x55e671ca25b0
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL session_create_request:2540 Done.
2023-03-16 17:33:30.126 thread(1) tag(11) INFO session_add_request:960 Starting. sess=0x55e671c9f820, req=0x55e671ca25b0
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL session_add_request_unsafe:925 Starting.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL session_add_request_unsafe:944 Total requests in the queue: 1
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL session_add_request_unsafe:946 Done.
2023-03-16 17:33:30.126 thread(1) tag(11) INFO session_add_request:968 Done.
2023-03-16 17:33:30.126 thread(1) tag(11) INFO build_read_request_connected:503 Done
2023-03-16 17:33:30.126 thread(1) tag(11) INFO tag_read_start:336 Done.
2023-03-16 17:33:30.126 thread(1) tag(11) INFO plc_tag_read:1737 Done
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL session_handler:1162 in SESSION_IDLE state.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL session_handler:1168 There are 1 requests pending before cleanup and sending.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL get_payload_size:1673 Starting.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL get_payload_size:1687 Done.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO process_requests:1444 1 requests to process.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO pack_requests:1708 Starting.
2023-03-16 17:33:30.126 thread(3) tag(11) INFO pack_requests:1718 Only one request, so done.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1810 Starting.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL prepare_request:1839 cpf_targ_conn_id=fff27a3b
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1847 Preparing connected packet with connection ID 7525a1d2 and s                                                                                                                                                                                 equence ID 62(3e)
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1854 Prepared packet of size 68
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1855 00000 70 00 2c 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1855 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1855 00032 a1 00 04 00 3b 7a f2 ff b1 00 18 00 3e 00 52 07
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1855 00048 91 0c 5f 31 6d 73 5f 41 75 78 44 49 4e 54 01 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1855 00064 00 00 00 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO prepare_request:1857 Done.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1870 Starting.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1883 Sending packet of size 68
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1884 00000 70 00 2c 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1884 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1884 00032 a1 00 04 00 3b 7a f2 ff b1 00 18 00 3e 00 52 07
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1884 00048 91 0c 5f 31 6d 73 5f 41 75 78 44 49 4e 54 01 00
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1884 00064 00 00 00 00
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL socket_write:1877 Starting.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL socket_write:1999 Done: result = 68.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO send_eip_request:1926 Done.
2023-03-16 17:33:30.126 thread(3) tag(0) INFO recv_eip_response:1946 Starting.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL socket_read:1754 Starting.
2023-03-16 17:33:30.126 thread(3) tag(0) DETAIL socket_read:1786 Immediate read attempt did not succeed, now wait for select().
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.126 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1814 Socket can read data.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1866 Done: result 24.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1754 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1866 Done: result 32.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2017 request received all needed data (56 bytes of 56).
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00000 70 00 20 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00032 a1 00 04 00 d2 a1 25 75 b1 00 0c 00 3e 00 d2 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00048 00 00 c4 00 11 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2026 Done.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1552 Starting.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1561 Got single response packet.  Copying 56 bytes unchanged.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1650 Unpacked packet:
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00000 70 00 20 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00032 a1 00 04 00 d2 a1 25 75 b1 00 0c 00 3e 00 d2 00
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00048 00 00 c4 00 11 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(11) DETAIL unpack_response:1660 Done.
2023-03-16 17:33:30.127 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from process_requests:1532.
2023-03-16 17:33:30.127 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from process_requests:1532.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL plc_tag_generic_tickler:281 Tickling tag 11.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL plc_tag_generic_tickler:386 Done.
2023-03-16 17:33:30.127 thread(2) tag(0) DETAIL check_read_status_connected:1410 type byte = 196 (c4)
2023-03-16 17:33:30.127 thread(2) tag(0) INFO check_read_status_connected:1471 Got 4 bytes of data
2023-03-16 17:33:30.127 thread(2) tag(0) DETAIL rc_dec_impl:242 Calling cleanup functions due to call at check_read_status_conn                                                                                                                                                                                 ected:1504 for 0x55e671ca25b0.
2023-03-16 17:33:30.127 thread(2) tag(0) INFO refcount_cleanup:256 Starting
2023-03-16 17:33:30.127 thread(2) tag(0) DETAIL request_destroy:2559 Starting.
2023-03-16 17:33:30.127 thread(2) tag(0) DETAIL request_destroy:2568 Done.
2023-03-16 17:33:30.127 thread(2) tag(0) INFO refcount_cleanup:268 Done.
2023-03-16 17:33:30.127 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from tag_tickler_func:569.
2023-03-16 17:33:30.127 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from tag_tickler_func:569.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL plc_tag_generic_tickler:281 Tickling tag 11.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL plc_tag_generic_tickler:386 Done.
**read tag in 1 ms**
2023-03-16 17:33:30.127 thread(1) tag(11) INFO plc_tag_read:1607 Starting.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO tag_read_start:307 Starting
2023-03-16 17:33:30.127 thread(1) tag(11) INFO build_read_request_connected:418 Starting.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL session_create_request:2517 Starting.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO rc_alloc_impl:111 Starting, called from session_create_request:2526
2023-03-16 17:33:30.127 thread(1) tag(11) INFO rc_alloc_impl:130 Done
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL rc_alloc_impl:135 Returning memory pointer 0x55e671ca25b0
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL session_create_request:2540 Done.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO session_add_request:960 Starting. sess=0x55e671c9f820, req=0x55e671ca25b0
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL session_add_request_unsafe:925 Starting.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL session_add_request_unsafe:944 Total requests in the queue: 1
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL session_add_request_unsafe:946 Done.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO session_add_request:968 Done.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO build_read_request_connected:503 Done
2023-03-16 17:33:30.127 thread(1) tag(11) INFO tag_read_start:336 Done.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO plc_tag_read:1737 Done
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL session_handler:1162 in SESSION_IDLE state.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL session_handler:1168 There are 1 requests pending before cleanup and sending.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL get_payload_size:1673 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL get_payload_size:1687 Done.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO process_requests:1444 1 requests to process.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO pack_requests:1708 Starting.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO pack_requests:1718 Only one request, so done.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1810 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL prepare_request:1839 cpf_targ_conn_id=fff27a3b
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1847 Preparing connected packet with connection ID 7525a1d2 and s                                                                                                                                                                                 equence ID 63(3f)
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1854 Prepared packet of size 68
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1855 00000 70 00 2c 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1855 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1855 00032 a1 00 04 00 3b 7a f2 ff b1 00 18 00 3f 00 52 07
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1855 00048 91 0c 5f 31 6d 73 5f 41 75 78 44 49 4e 54 01 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1855 00064 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO prepare_request:1857 Done.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1870 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1883 Sending packet of size 68
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1884 00000 70 00 2c 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1884 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1884 00032 a1 00 04 00 3b 7a f2 ff b1 00 18 00 3f 00 52 07
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1884 00048 91 0c 5f 31 6d 73 5f 41 75 78 44 49 4e 54 01 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1884 00064 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_write:1877 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_write:1999 Done: result = 68.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO send_eip_request:1926 Done.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:1946 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1754 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1786 Immediate read attempt did not succeed, now wait for select().
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1814 Socket can read data.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1866 Done: result 24.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1754 Starting.
2023-03-16 17:33:30.127 thread(3) tag(0) DETAIL socket_read:1866 Done: result 32.
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2017 request received all needed data (56 bytes of 56).
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00000 70 00 20 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00032 a1 00 04 00 d2 a1 25 75 b1 00 0c 00 3f 00 d2 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2019 00048 00 00 c4 00 12 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(0) INFO recv_eip_response:2026 Done.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1552 Starting.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1561 Got single response packet.  Copying 56 bytes unchanged.
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1650 Unpacked packet:
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00000 70 00 20 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00032 a1 00 04 00 d2 a1 25 75 b1 00 0c 00 3f 00 d2 00
2023-03-16 17:33:30.127 thread(3) tag(11) INFO unpack_response:1651 00048 00 00 c4 00 12 00 00 00
2023-03-16 17:33:30.127 thread(3) tag(11) DETAIL unpack_response:1660 Done.
2023-03-16 17:33:30.127 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from process_requests:1532.
2023-03-16 17:33:30.127 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from process_requests:1532.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL check_read_status_connected:1410 type byte = 196 (c4)
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.127 thread(2) tag(11) DETAIL tag_tickler_func:603 Skipping tag as it is already locked.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO check_read_status_connected:1471 Got 4 bytes of data
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL rc_dec_impl:242 Calling cleanup functions due to call at check_read_status_con                                                                                                                                                                                 nected:1504 for 0x55e671ca25b0.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO refcount_cleanup:256 Starting
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL request_destroy:2559 Starting.
2023-03-16 17:33:30.127 thread(1) tag(11) DETAIL request_destroy:2568 Done.
2023-03-16 17:33:30.127 thread(1) tag(11) INFO refcount_cleanup:268 Done.
2023-03-16 17:33:30.227 thread(2) tag(0) DETAIL tag_tickler_func:636 Tag tickler thread timed out waiting for something to do.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL session_handler:1162 in SESSION_IDLE state.
2023-03-16 17:33:30.227 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.227 thread(2) tag(11) DETAIL plc_tag_generic_tickler:281 Tickling tag 11.
2023-03-16 17:33:30.227 thread(2) tag(11) DETAIL plc_tag_generic_tickler:386 Done.
2023-03-16 17:33:30.227 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from tag_tickler_func:569.
2023-03-16 17:33:30.227 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from tag_tickler_func:569.
2023-03-16 17:33:30.227 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.227 thread(2) tag(11) DETAIL plc_tag_generic_tickler:281 Tickling tag 11.
2023-03-16 17:33:30.227 thread(2) tag(11) DETAIL plc_tag_generic_tickler:386 Done.
**read tag in 100 ms**
2023-03-16 17:33:30.227 thread(1) tag(11) INFO plc_tag_read:1607 Starting.
2023-03-16 17:33:30.227 thread(1) tag(11) INFO tag_read_start:307 Starting
2023-03-16 17:33:30.227 thread(1) tag(11) INFO build_read_request_connected:418 Starting.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL session_create_request:2517 Starting.
2023-03-16 17:33:30.227 thread(1) tag(11) INFO rc_alloc_impl:111 Starting, called from session_create_request:2526
2023-03-16 17:33:30.227 thread(1) tag(11) INFO rc_alloc_impl:130 Done
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL rc_alloc_impl:135 Returning memory pointer 0x55e671ca25b0
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL session_create_request:2540 Done.
2023-03-16 17:33:30.227 thread(1) tag(11) INFO session_add_request:960 Starting. sess=0x55e671c9f820, req=0x55e671ca25b0
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL session_add_request_unsafe:925 Starting.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL session_add_request_unsafe:944 Total requests in the queue: 1
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL session_add_request_unsafe:946 Done.
2023-03-16 17:33:30.227 thread(1) tag(11) INFO session_add_request:968 Done.
2023-03-16 17:33:30.227 thread(1) tag(11) INFO build_read_request_connected:503 Done
2023-03-16 17:33:30.227 thread(1) tag(11) INFO tag_read_start:336 Done.
2023-03-16 17:33:30.227 thread(1) tag(11) INFO plc_tag_read:1737 Done
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL session_handler:1162 in SESSION_IDLE state.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL session_handler:1168 There are 1 requests pending before cleanup and sending.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL get_payload_size:1673 Starting.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL get_payload_size:1687 Done.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO process_requests:1444 1 requests to process.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO pack_requests:1708 Starting.
2023-03-16 17:33:30.227 thread(3) tag(11) INFO pack_requests:1718 Only one request, so done.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1810 Starting.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL prepare_request:1839 cpf_targ_conn_id=fff27a3b
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1847 Preparing connected packet with connection ID 7525a1d2 and s                                                                                                                                                                                 equence ID 64(40)
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1854 Prepared packet of size 68
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1855 00000 70 00 2c 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1855 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1855 00032 a1 00 04 00 3b 7a f2 ff b1 00 18 00 40 00 52 07
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1855 00048 91 0c 5f 31 6d 73 5f 41 75 78 44 49 4e 54 01 00
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1855 00064 00 00 00 00
2023-03-16 17:33:30.227 thread(3) tag(0) INFO prepare_request:1857 Done.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1870 Starting.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1883 Sending packet of size 68
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1884 00000 70 00 2c 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1884 00016 00 00 00 00 00 00 00 00 00 00 00 00 01 00 02 00
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1884 00032 a1 00 04 00 3b 7a f2 ff b1 00 18 00 40 00 52 07
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1884 00048 91 0c 5f 31 6d 73 5f 41 75 78 44 49 4e 54 01 00
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1884 00064 00 00 00 00
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL socket_write:1877 Starting.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL socket_write:1999 Done: result = 68.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO send_eip_request:1926 Done.
2023-03-16 17:33:30.227 thread(3) tag(0) INFO recv_eip_response:1946 Starting.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL socket_read:1754 Starting.
2023-03-16 17:33:30.227 thread(3) tag(0) DETAIL socket_read:1786 Immediate read attempt did not succeed, now wait for select().
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.227 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.228 thread(1) tag(11) DETAIL check_read_request_status:1106 Read not ready with status PLCTAG_STATUS_PENDIN                                                                                                                                                                                 G.
2023-03-16 17:33:30.228 thread(1) tag(11) DETAIL check_read_status_connected:1345 Read request status is not OK.
2023-03-16 17:33:30.228 thread(3) tag(0) DETAIL socket_read:1814 Socket can read data.
2023-03-16 17:33:30.228 thread(3) tag(0) DETAIL socket_read:1866 Done: result 24.
2023-03-16 17:33:30.228 thread(3) tag(0) DETAIL socket_read:1754 Starting.
2023-03-16 17:33:30.228 thread(3) tag(0) DETAIL socket_read:1866 Done: result 32.
2023-03-16 17:33:30.228 thread(3) tag(0) INFO recv_eip_response:2017 request received all needed data (56 bytes of 56).
2023-03-16 17:33:30.228 thread(3) tag(0) INFO recv_eip_response:2019 00000 70 00 20 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.228 thread(3) tag(0) INFO recv_eip_response:2019 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00
2023-03-16 17:33:30.228 thread(3) tag(0) INFO recv_eip_response:2019 00032 a1 00 04 00 d2 a1 25 75 b1 00 0c 00 40 00 d2 00
2023-03-16 17:33:30.228 thread(3) tag(0) INFO recv_eip_response:2019 00048 00 00 c4 00 12 00 00 00
2023-03-16 17:33:30.228 thread(3) tag(0) INFO recv_eip_response:2026 Done.
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1552 Starting.
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1561 Got single response packet.  Copying 56 bytes unchanged.
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1650 Unpacked packet:
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1651 00000 70 00 20 00 53 41 02 40 00 00 00 00 00 00 00 00
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1651 00016 00 00 00 00 00 00 00 00 00 00 00 00 00 00 02 00
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1651 00032 a1 00 04 00 d2 a1 25 75 b1 00 0c 00 40 00 d2 00
2023-03-16 17:33:30.228 thread(3) tag(11) INFO unpack_response:1651 00048 00 00 c4 00 12 00 00 00
2023-03-16 17:33:30.228 thread(3) tag(11) DETAIL unpack_response:1660 Done.
2023-03-16 17:33:30.228 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from process_requests:1532.
2023-03-16 17:33:30.228 thread(3) tag(11) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from process_requests:1532.
2023-03-16 17:33:30.228 thread(1) tag(11) DETAIL check_read_status_connected:1410 type byte = 196 (c4)
2023-03-16 17:33:30.228 thread(1) tag(11) INFO check_read_status_connected:1471 Got 4 bytes of data
2023-03-16 17:33:30.228 thread(1) tag(11) DETAIL rc_dec_impl:242 Calling cleanup functions due to call at check_read_status_con                                                                                                                                                                                 nected:1504 for 0x55e671ca25b0.
2023-03-16 17:33:30.228 thread(1) tag(11) INFO refcount_cleanup:256 Starting
2023-03-16 17:33:30.228 thread(1) tag(11) DETAIL request_destroy:2559 Starting.
2023-03-16 17:33:30.228 thread(1) tag(11) DETAIL request_destroy:2568 Done.
2023-03-16 17:33:30.228 thread(1) tag(11) INFO refcount_cleanup:268 Done.
2023-03-16 17:33:30.228 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.228 thread(2) tag(11) DETAIL plc_tag_generic_tickler:281 Tickling tag 11.
2023-03-16 17:33:30.228 thread(2) tag(11) DETAIL plc_tag_generic_tickler:386 Done.
2023-03-16 17:33:30.228 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:220 Starting. Called from tag_tickler_func:569.
2023-03-16 17:33:30.228 thread(2) tag(0) DETAIL plc_tag_tickler_wake_impl:233 Done. Called from tag_tickler_func:569.
2023-03-16 17:33:30.228 thread(2) tag(11) DETAIL tag_tickler_func:550 Tickling tag 11.
2023-03-16 17:33:30.228 thread(2) tag(11) DETAIL plc_tag_generic_tickler:281 Tickling tag 11.
2023-03-16 17:33:30.228 thread(2) tag(11) DETAIL plc_tag_generic_tickler:386 Done.
**read tag in 1 ms**

@kyle-github
Copy link
Member

I have not been able to duplicate this locally, but I have a few more ideas to try.

@ronytigo
Copy link
Author

Are you trying on Ubuntu?
Tell me what to do.

@kyle-github
Copy link
Member

Sorry this is taking so long. Still sick.

@kyle-github
Copy link
Member

I will have more time now so this is back near the head of the queue. I need to rewire my test set up to give me a wired connection to my PLC. Right now, the only thing I have is wireless and that has a lot of noise that would hide these problems.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
performance question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@kyle-github @timyhac @ronytigo