search

n0-computer / iroh

A toolkit for building distributed applications
https://iroh.computer
Apache License 2.0
2.27k stars 145 forks source link

Optimize data transfer delay #2328

Closed zh522130 closed 3 months ago

zh522130 commented 3 months ago

I noticed that when the connection type is ConnectionType::Mixed, the data transfer delay seems to include the delay from netcheck, and under the network environment mentioned at https://github.com/n0-computer/iroh/issues/2327, the transfer delay can be further amplified. The log only captures instances where the transmission delay was very high. I'm not certain if other connection types include this part of the delay. However, from my test results, it seems that iroh's average delay is somewhat higher than that of Tailscale, possibly slower by about 1ms in a local area network condition (this is not very precise, as the router itself can also have fluctuations).

Code:

loop {
        let now = std::time::Instant::now();
        println!("====================> start send");
        let (mut send, mut recv) = conn.open_bi().await?;
        send.write_all(message).await?;

        // Call `finish` to close the send side of the connection gracefully.
        send.finish().await?;
        let message = recv.read_to_end(4096).await?;
        let tk_ms = now.elapsed().as_millis();
        if tk_ms > 2000 {
            println!("xxxxxxxxxxxxxxxxx=> took: {}ms\n\n\n", now.elapsed().as_millis());
        } else {
            println!("took: {}ms", now.elapsed().as_millis());
        }
        let message = String::from_utf8(message)?;
        println!("received: {message}");

        let conninfo = endpoint.connection_info(remote_node_id);
        if let Some(con_info) = conninfo {
            println!("connect type:{:?}", con_info.conn_type);
        }
        println!("====================> end send");
        sleep(Duration::from_millis(500)).await;
    }

Log:

====================> start send
2024-05-27T01:35:39.001511Z  INFO poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: new connection type typ=mixed
2024-05-27T01:35:39.001819Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}:want_call_me_maybe: iroh_net::magicsock::node_map::node_state: best addr not set: need full ping
2024-05-27T01:35:39.002343Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:39.002346Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:rtt-actor: iroh_net::endpoint::rtt_actor: Congestion controller state reset node_id=w6fj3gwbwqpowxjr new_type=Mixed(100.101.102.121:57750, RelayUrl("https://custom.relay.:12346/"))
2024-05-27T01:35:39.002596Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:39.041096Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: pong not received in timeout tx=6f44cbe2e1c68a53c2041e62 addr=UDP(192.168.193.121:57750)
2024-05-27T01:35:39.041369Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: pong not received in timeout tx=3902de0a79fe1f48ce587885 addr=UDP(100.101.102.121:57750)
2024-05-27T01:35:39.041571Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: pong not received in timeout tx=158f4c6b03b8e9d3f9d70b0a addr=UDP(10.0.0.222:57750)
2024-05-27T01:35:39.041827Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: pong not received in timeout tx=7b316b8010c9442bc70cbf79 addr=UDP(115.226.50.123:57750)
2024-05-27T01:35:39.085770Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: wmi::connection: Calling CoCreateInstance for CLSID_WbemLocator    
2024-05-27T01:35:39.085937Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:portmapper.service: iroh_net::portmapper: getting a port mapping for 192.168.246.109:64227 -> None
2024-05-27T01:35:39.086316Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: wmi::connection: Got locator IWbemLocator(IUnknown(0x1448fcdbba0))
2024-05-27T01:35:39.086660Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:portmapper.service:upnp: igd_next::aio::tokio: sending broadcast request to: 239.255.255.250:1900 on interface: Ok(0.0.0.0:56613)
2024-05-27T01:35:39.086682Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: wmi::connection: Calling ConnectServer
2024-05-27T01:35:39.088780Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: wmi::connection: Got service IWbemServices(IUnknown(0x1448fcaff20))
2024-05-27T01:35:39.088992Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: wmi::connection: Calling CoSetProxyBlanket
2024-05-27T01:35:39.091453Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Local interfaces if_state=1. {0C92EAB2-79EA-11EE-87ED-806E6F6E6963} Loopback ipv4=[127.0.0.1/8] ipv6=[::1/128]; 4. {142A8614-AF6C-4C76-B418-6F04490CA730} Wireless80211 ipv4=[169.254.185.32/16] ipv6=[fe80::4ce8:a1c8:5fe8:84f5/64]; 10. {4EC851CA-D4B7-4714-B93A-F1B68CBBF873} Ethernet ipv4=[192.168.159.1/24] ipv6=[fe80::e1d9:1eb6:5d3f:4033/64]; 11. {83F49C33-44F5-41DD-8ECC-3835FF33B91F} Wireless80211 ipv4=[192.168.246.109/24] ipv6=[2408:843c:2010:285b:ba67:bed5:4c32:3574/64, 2408:843c:2010:285b:84ca:bcf4:3133:f80/128, fe80::b08f:65a7:c73d:234c/64]; 14. {A8A861FC-B814-4EA3-A987-9CF67CCB1BD6} Ethernet ipv4=[10.0.0.63/24] ipv6=[fe80::1e24:3722:7906:cccc/64]; 15. {ABCC6E0B-AD39-47B6-BA95-A4ABB576E8BD} Ethernet ipv4=[169.254.166.205/16] ipv6=[fe80::6e19:d84b:d3f:3c88/64]; 18. {B90598F2-B28D-40CC-B3DD-2026601D9D50} Wireless80211 ipv4=[169.254.74.187/16] ipv6=[fe80::2fe1:97b:3b78:128a/64]; 22. {FA05C7A1-D742-4942-9AEE-39E8E6F323EB} Ethernet ipv4=[192.168.254.1/24] ipv6=[fe80::dea8:53f7:f4cf:8206/64]; 43. {F7859FCE-C3B0-469A-B500-553D86027A9B} Ethernet ipv4=[172.27.112.1/20] ipv6=[fe80::8836:ddbd:34a2:9dfb/64]; 65. {5F056F55-365A-4F2D-9150-7B5E58AE9405} Ethernet ipv4=[192.168.80.1/20] ipv6=[fe80::acbd:7bff:9ab9:cb13/64];
2024-05-27T01:35:39.092098Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: starting probe
2024-05-27T01:35:39.092104Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: starting probe
2024-05-27T01:35:39.092345Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: Performing DNS A lookup for relay addr proto=StunIpv4 hostname=custom.relay.
2024-05-27T01:35:39.092554Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: Performing DNS AAAA lookup for relay addr proto=StunIpv6 hostname=custom.relay.
2024-05-27T01:35:39.102785Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 0ns to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: sending StunIpv4 probe relay_addr=49.116.213.128:13478 txid=transaction id (0x638AC416763FA02BA92825B8)
2024-05-27T01:35:39.102827Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 0ns to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: sending StunIpv6 probe relay_addr=[2408:4102:105c:5364:7ae1:c1f3:df13:ca0e]:13478 txid=transaction id (0xBB09070B664DB4972873139E)
2024-05-27T01:35:39.110714Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=CallMeMaybe(CallMeMaybe { my_numbers: [115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750] })}: iroh_net::magicsock::node_map: received call-me-maybe endpoints=[115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750]
2024-05-27T01:35:39.111160Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=CallMeMaybe(CallMeMaybe { my_numbers: [115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750] })}: iroh_net::magicsock::node_map::node_state: updated endpoint paths from call-me-maybe paths=[10.0.0.222:57750{ }, 100.101.102.121:57750{ }, 115.226.50.123:57750{ }, 192.168.193.121:57750{ }]
2024-05-27T01:35:39.111501Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=CallMeMaybe(CallMeMaybe { my_numbers: [115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750] })}: iroh_net::magicsock::node_map::node_state: relay path needs ping url=https://custom.relay.:12346/
2024-05-27T01:35:39.111717Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=CallMeMaybe(CallMeMaybe { my_numbers: [115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750] })}: iroh_net::magicsock::node_map::node_state: prune addresses: 0 pruned paths=[10.0.0.222:57750{ }, 100.101.102.121:57750{ }, 115.226.50.123:57750{ }, 192.168.193.121:57750{ }]
2024-05-27T01:35:39.111945Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=CallMeMaybe(CallMeMaybe { my_numbers: [115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750] })}: iroh_net::magicsock::node_map::node_state: sending pings to endpoint ping_dsts=[ UDP(10.0.0.222:57750)  UDP(100.101.102.121:57750)  UDP(115.226.50.123:57750)  UDP(192.168.193.121:57750) ] dst=w6fj3gwbwqpowxjr paths=[10.0.0.222:57750{ }, 100.101.102.121:57750{ }, 115.226.50.123:57750{ }, 192.168.193.121:57750{ }]
2024-05-27T01:35:39.112203Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=CallMeMaybe(CallMeMaybe { my_numbers: [115.226.50.123:57750, 10.0.0.222:57750, 100.101.102.121:57750, 192.168.193.121:57750] })}: iroh_net::magicsock: send disco message (relay) node=w6fj3gwbwqpowxjr url=https://custom.relay.:12346/ msg=Ping(tx=8bee05e1ab4edf31bf96a2b9)
2024-05-27T01:35:39.112462Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:39.112706Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:39.179352Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 79.72184ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: starting probe
2024-05-27T01:35:39.179352Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 79.72184ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: starting probe
2024-05-27T01:35:39.179954Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 79.72184ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: Performing DNS AAAA lookup for relay addr proto=StunIpv6 hostname=custom.relay.
2024-05-27T01:35:39.180225Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 79.72184ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: Performing DNS A lookup for relay addr proto=StunIpv4 hostname=custom.relay.
2024-05-27T01:35:39.195060Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv4 after 79.72184ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: sending StunIpv4 probe relay_addr=49.116.213.128:13478 txid=transaction id (0x65E1772981732DE0BFD505B4)
2024-05-27T01:35:39.195127Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 79.72184ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: sending StunIpv6 probe relay_addr=[2408:4102:105c:5364:7ae1:c1f3:df13:ca0e]:13478 txid=transaction id (0x9DB16C2C0318D8F54AF46D0B)
2024-05-27T01:35:39.197729Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor: iroh_net::netcheck: received known STUN packet src=49.116.213.128:13478 txn=transaction id (0x638AC416763FA02BA92825B8)
2024-05-27T01:35:39.198051Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: finished probe probe_report=ProbeReport { ipv4_can_send: true, ipv6_can_send: false, icmpv4: None, icmpv6: None, latency: Some(95.2974ms), probe: StunIpv4 { delay: 0ns, node: RelayNode { url: RelayUrl("https://custom.relay.:12346/"), stun_only: false, stun_port: 13478 } }, addr: Some(122.193.198.158:19052) }
2024-05-27T01:35:39.198413Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Have enough probe reports, aborting further probes soon reports=1 delay=95.2974ms
2024-05-27T01:35:39.259301Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 159.44368ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: starting probe
2024-05-27T01:35:39.259660Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 159.44368ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: Performing DNS AAAA lookup for relay addr proto=StunIpv6 hostname=custom.relay.
2024-05-27T01:35:39.275146Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor:run_probe{probe=STUN Ipv6 after 159.44368ms to https://custom.relay.:12346/}: iroh_net::netcheck::reportgen: sending StunIpv6 probe relay_addr=[2408:4102:105c:5364:7ae1:c1f3:df13:ca0e]:13478 txid=transaction id (0xD477767DDFCCAB9C3A8764C1)
2024-05-27T01:35:39.311476Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:hairpin.actor: iroh_net::netcheck::reportgen::hairpin: hairpinning done in 112.5798ms, res: false
2024-05-27T01:35:39.312031Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: all tasks done
2024-05-27T01:35:39.312359Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: aborting 4 probe sets, already have enough reports
2024-05-27T01:35:39.312627Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: Sending report to netcheck actor
2024-05-27T01:35:39.312905Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor:reportgen.actor: iroh_net::netcheck::reportgen: reportgen actor finished
2024-05-27T01:35:39.313167Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:netcheck.actor: iroh_net::netcheck: Report { udp: true, ipv6: false, ipv4: true, ipv6_can_send: false, ipv4_can_send: true, os_has_ipv6: true, icmpv4: None, icmpv6: None, mapping_varies_by_dest_ip: None, mapping_varies_by_dest_ipv6: None, hair_pinning: Some(false), portmap_probe: None, preferred_relay: Some(RelayUrl("https://custom.relay.:12346/")), relay_latency: RelayLatencies({RelayUrl("https://custom.relay.:12346/"): 95.2974ms}), relay_v4_latency: RelayLatencies({RelayUrl("https://custom.relay.:12346/"): 95.2974ms}), relay_v6_latency: RelayLatencies({}), global_v4: Some(122.193.198.158:19052), global_v6: None, captive_portal: None }
2024-05-27T01:35:40.013474Z  INFO poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: new connection type typ=mixed
2024-05-27T01:35:40.013861Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}:want_call_me_maybe: iroh_net::magicsock::node_map::node_state: best addr not set: need full ping
2024-05-27T01:35:40.014308Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:40.014335Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:rtt-actor: iroh_net::endpoint::rtt_actor: Congestion controller state reset node_id=w6fj3gwbwqpowxjr new_type=Mixed(10.0.0.222:57750, RelayUrl("https://custom.relay.:12346/"))
2024-05-27T01:35:40.014688Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:41.025287Z  INFO poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: new connection type typ=mixed
2024-05-27T01:35:41.025701Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}:want_call_me_maybe: iroh_net::magicsock::node_map::node_state: best addr not set: need full ping
2024-05-27T01:35:41.026240Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:41.026251Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:rtt-actor: iroh_net::endpoint::rtt_actor: Congestion controller state reset node_id=w6fj3gwbwqpowxjr new_type=Mixed(192.168.193.121:57750, RelayUrl("https://custom.relay.:12346/"))
2024-05-27T01:35:41.026530Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:42.033206Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}:want_call_me_maybe: iroh_net::magicsock::node_map::node_state: best addr not set: need full ping
2024-05-27T01:35:42.033642Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: prune addresses: 0 pruned paths=[10.0.0.222:57750{ ping-sent(2.9211795s ago) }, 100.101.102.121:57750{ ping-sent(2.9211733s ago) }, 115.226.50.123:57750{ ping-sent(2.921166s ago) }, 192.168.193.121:57750{ ping-sent(2.9211594s ago) }]
2024-05-27T01:35:42.033959Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: sending pings to endpoint ping_dsts=[] dst=w6fj3gwbwqpowxjr paths=[10.0.0.222:57750{ ping-sent(2.9214973s ago) }, 100.101.102.121:57750{ ping-sent(2.9214908s ago) }, 115.226.50.123:57750{ ping-sent(2.9214835s ago) }, 192.168.193.121:57750{ ping-sent(2.9214765s ago) }]
2024-05-27T01:35:42.034258Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: queue call-me-maybe url=https://custom.relay.:12346/
2024-05-27T01:35:42.034438Z DEBUG poll_send{me=27evu2sogrbp5m6q}:handle_ping_action: iroh_net::magicsock: send disco message (relay) node=w6fj3gwbwqpowxjr url=https://custom.relay.:12346/ msg=CallMeMaybe
2024-05-27T01:35:42.034668Z DEBUG poll_send{me=27evu2sogrbp5m6q}:handle_ping_action: iroh_net::magicsock: call-me-maybe sent dstkey=w6fj3gwbwqpowxjr relayurl=RelayUrl("https://custom.relay.:12346/")
2024-05-27T01:35:42.034961Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:42.035142Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:42.035424Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:42.035635Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:43.045182Z  INFO poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}: iroh_net::magicsock::node_map::node_state: new connection type typ=mixed
2024-05-27T01:35:43.045677Z DEBUG poll_send{me=27evu2sogrbp5m6q}:get_send_addrs{node=w6fj3gwbwqpowxjr}:want_call_me_maybe: iroh_net::magicsock::node_map::node_state: best addr not set: need full ping
2024-05-27T01:35:43.046062Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor: iroh_net::magicsock::relay_actor: connect relay https://custom.relay.:12346/ for peer Some(PublicKey(w6fj3gwbwqpowxjr))
2024-05-27T01:35:43.046073Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:rtt-actor: iroh_net::endpoint::rtt_actor: Congestion controller state reset node_id=w6fj3gwbwqpowxjr new_type=Mixed(115.226.50.123:57750, RelayUrl("https://custom.relay.:12346/"))
2024-05-27T01:35:43.046263Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:relay-actor:client: iroh_net::relay::http::client: connect: send, current client true
2024-05-27T01:35:43.301525Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:portmapper.service: iroh_net::portmapper: failed to get a port mapping IO error: search timed out
2024-05-27T01:35:43.302663Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:portmapper.service:portmapper.probe: igd_next::aio::tokio: sending broadcast request to: 239.255.255.250:1900 on interface: Ok(0.0.0.0:56632)
2024-05-27T01:35:43.306530Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:portmapper.service:portmapper.probe: iroh_net::portmapper::nat_pmp: probe failed: 远程主机强迫关闭了一个现有的连接。 (os error 10054)
2024-05-27T01:35:43.309855Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:portmapper.service:portmapper.probe: iroh_net::portmapper::pcp: probe failed: 远程主机强迫关闭了一个现有的连接。 (os error 10054)
2024-05-27T01:35:43.504284Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor: iroh_net::magicsock: scheduling periodic_stun to run in 25s
2024-05-27T01:35:43.504590Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor: iroh_net::magicsock: endpoint update done (refresh-for-peering)
2024-05-27T01:35:43.504985Z DEBUG magic_ep{me=27evu2sogrbp5m6q}:magicsock{me=27evu2sogrbp5m6q}:actor:disco_in{node=w6fj3gwbwqpowxjr src=Relay(https://custom.relay.:12346/, w6fj3gwbwqpowxjr)}:handle_disco{dm=Pong(Pong { tx_id: TransactionId(0x8BEE05E1AB4EDF31BF96A2B9), ping_observed_addr: Relay(RelayUrl("https://custom.relay.:12346/")) })}:handle_pong{m=Pong { tx_id: TransactionId(0x8BEE05E1AB4EDF31BF96A2B9), ping_observed_addr: Relay(RelayUrl("https://custom.relay.:12346/")) } src=Relay(RelayUrl("https://custom.relay.:12346/"))}: iroh_net::magicsock::node_map::node_state: received pong tx=8bee05e1ab4edf31bf96a2b9 src=Relay(https://custom.relay.:12346/) reported_ping_src=Relay(https://custom.relay.:12346/) ping_dst=Relay(https://custom.relay.:12346/) is_relay=true latency=4392
xxxxxxxxxxxxxxxxx=> send took: 4504ms
flub commented 3 months ago

Not conclusive, but I suspect the netcheck logs are there just by chance because it happens regularly - about every 30s. If you look at the logs before this you might be able to see why netcheck was triggered.

Looking at where the gaps are in the timestamps it looks like always around two locations:

Is it possible you only enabled logs for the iroh-net crate? Otherwise you might also see activity from the DNS library and the HTTP & TLS libraries around these points I suspect.

zh522130 commented 3 months ago

Not conclusive, but I suspect the netcheck logs are there just by chance because it happens regularly - about every 30s

please refer to the INFO-level.log file, It seems that most of the time, the recurring high latency only takes a few seconds.

Is it possible you only enabled logs for the iroh-net crate? Otherwise you might also see activity from the DNS library and the HTTP & TLS libraries around these points I suspect.

I am still learning Rust and am not very proficient. How can I enable logs for other crates? I tried printing through the following code. 

    let subscriber = tracing_subscriber::registry()
        .with(
            tracing_subscriber::fmt::layer()
                .with_writer(Arc::new(log_file)
                .with_max_level(tracing::Level::DEBUG))
                .with_ansi(false),
        )
        .with(
            tracing_subscriber::fmt::layer()
                .with_writer(std::io::stdout.with_max_level(tracing::Level::DEBUG)),
        );
    subscriber.init();

Cargo.toml:

iroh-base = { version = "0.17.0", features = [
    "key",
] }
iroh-net = { version = "0.17.0", features = ["test-utils"]}
iroh-metrics = { version = "0.17.0", default-features = false }

I have re-uploaded two log files. The INFO-level.log file mainly tests for the occurrence cycle, and the TRACE-level.log file mainly records the complete TRACE-level log from the start of the code execution to the first occurrence of high latency.

INFO-level.log

TRACE-level.log

zh522130 commented 3 months ago

@flub By tracing the code, I found the code that causes the delay. In the magicsock.rs file, The function call path is as follows:

async fn handle_actor_message(&mut self, msg: ActorMessage) -> bool {
    match msg {
        ActorMessage::NetcheckReport(report, why) => {
            >> self.handle_netcheck_report(report).await
                >> self.store_endpoints_update(report).await
                    >> let LocalAddresses {
                                regular: mut ips,
                                loopback,
                            } = LocalAddresses::new() >> let ifaces = netdev::interface::get_interfaces();
        }
}

Ultimately, netdev::interface::get_interfaces() introduces additional latency. On my laptop, even after the fix through https://github.com/n0-computer/iroh/issues/2327, netdev::interface::get_interfaces() still takes over 10ms-20ms (on the Windows platform, unsure if the delay is related to device performance or platform). Consequently, in relay mode, a extra latency occurs at regular intervals.

flub commented 3 months ago

@zh522130 this can be closed now or are you still getting delays?

zh522130 commented 3 months ago

@zh522130 this can be closed now or are you still getting delays?

yes, close it