cargo-lambda icon indicating copy to clipboard operation
cargo-lambda copied to clipboard
verified publisher icon cargo-lambda

High CPU Utilization

Open taylor1791 opened this issue 3 years ago • 3 comments

Please forgive me if this is expected behavior. It surprised me and further investigation would require significant effort.

After creating a new project, running cargo lambda watch, and curl http://localhost:9000/lambda-url/<name>/, the cargo watch process becomes very busy. In fact, it occupies a whole core! After turning on as much logging as I could, I found the following cycle in the logs. I don't really know what to make of it, but it looks like something is generating HTTP traffic.

Is this a bug or expected behavior?

2022-10-18T02:03:18.170216Z TRACE ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:612: take? ("http", 127.0.0.1:9000): expiration = Some(90s)
2022-10-18T02:03:18.170249Z DEBUG ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:250: reuse idle connection for ("http", 127.0.0.1:9000)
2022-10-18T02:03:18.170387Z TRACE ThreadId(13) encode_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:107: new
2022-10-18T02:03:18.170425Z TRACE ThreadId(13) encode_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:1110: Client::encode method=GET, body=None
2022-10-18T02:03:18.170469Z TRACE ThreadId(13) encode_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:107: close time.busy=44.1µs time.idle=39.6µs
2022-10-18T02:03:18.170539Z DEBUG ThreadId(13) hyper::proto::h1::io: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/io.rs:320: flushed 117 bytes
2022-10-18T02:03:18.170560Z TRACE ThreadId(13) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:732: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2022-10-18T02:03:18.170696Z TRACE ThreadId(12) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:191: Conn::read_head
2022-10-18T02:03:18.170816Z TRACE ThreadId(12) hyper::proto::h1::io: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/io.rs:269: received 220 bytes
2022-10-18T02:03:18.170846Z TRACE ThreadId(12) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:75: new
2022-10-18T02:03:18.170881Z TRACE ThreadId(12) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:946: Response.parse bytes=220
2022-10-18T02:03:18.170921Z TRACE ThreadId(12) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:955: Response.parse Complete(220)
2022-10-18T02:03:18.170990Z TRACE ThreadId(12) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:75: close time.busy=113µs time.idle=31.6µs
2022-10-18T02:03:18.171025Z DEBUG ThreadId(12) hyper::proto::h1::io: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/io.rs:207: parsed 4 headers
2022-10-18T02:03:18.171042Z DEBUG ThreadId(12) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:222: incoming body is empty
2022-10-18T02:03:18.171067Z TRACE ThreadId(12) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:472: maybe_notify; read_from_io blocked
2022-10-18T02:03:18.171105Z TRACE ThreadId(12) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:732: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
2022-10-18T02:03:18.171130Z TRACE ThreadId(12) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:732: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
2022-10-18T02:03:18.171134Z TRACE ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:329: put; add idle connection for ("http", 127.0.0.1:9000)
2022-10-18T02:03:18.171223Z DEBUG ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:376: pooling idle connection for ("http", 127.0.0.1:9000)
2022-10-18T02:03:18.171252Z TRACE ThreadId(01) lambda_runtime: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/lambda_runtime-0.7.0/src/lib.rs:111: New event arrived (run loop)
2022-10-18T02:03:18.171277Z TRACE ThreadId(01) lambda_runtime: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/lambda_runtime-0.7.0/src/lib.rs:200: Waiting for next event (incoming loop)

2022-10-18T02:03:18.171351Z TRACE ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:612: take? ("http", 127.0.0.1:9000): expiration = Some(90s)
2022-10-18T02:03:18.171384Z DEBUG ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:250: reuse idle connection for ("http", 127.0.0.1:9000)
2022-10-18T02:03:18.171549Z TRACE ThreadId(12) encode_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:107: new
2022-10-18T02:03:18.171588Z TRACE ThreadId(12) encode_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:1110: Client::encode method=GET, body=None
2022-10-18T02:03:18.171640Z TRACE ThreadId(12) encode_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:107: close time.busy=52.0µs time.idle=40.8µs
2022-10-18T02:03:18.171706Z DEBUG ThreadId(12) hyper::proto::h1::io: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/io.rs:320: flushed 117 bytes
2022-10-18T02:03:18.171729Z TRACE ThreadId(12) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:732: flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
2022-10-18T02:03:18.171843Z TRACE ThreadId(13) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:191: Conn::read_head
2022-10-18T02:03:18.171878Z TRACE ThreadId(13) hyper::proto::h1::io: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/io.rs:269: received 220 bytes
2022-10-18T02:03:18.171907Z TRACE ThreadId(13) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:75: new
2022-10-18T02:03:18.171938Z TRACE ThreadId(13) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:946: Response.parse bytes=220
2022-10-18T02:03:18.171973Z TRACE ThreadId(13) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:955: Response.parse Complete(220)
2022-10-18T02:03:18.172036Z TRACE ThreadId(13) parse_headers: hyper::proto::h1::role: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/role.rs:75: close time.busy=97.3µs time.idle=31.8µs
2022-10-18T02:03:18.172070Z DEBUG ThreadId(13) hyper::proto::h1::io: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/io.rs:207: parsed 4 headers
2022-10-18T02:03:18.172086Z DEBUG ThreadId(13) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:222: incoming body is empty
2022-10-18T02:03:18.172106Z TRACE ThreadId(13) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:472: maybe_notify; read_from_io blocked
2022-10-18T02:03:18.172138Z TRACE ThreadId(13) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:732: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
2022-10-18T02:03:18.172155Z TRACE ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:329: put; add idle connection for ("http", 127.0.0.1:9000)
2022-10-18T02:03:18.172163Z TRACE ThreadId(13) hyper::proto::h1::conn: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/proto/h1/conn.rs:732: flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
2022-10-18T02:03:18.172188Z DEBUG ThreadId(01) hyper::client::pool: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.14.20/src/client/pool.rs:376: pooling idle connection for ("http", 127.0.0.1:9000)
2022-10-18T02:03:18.172216Z TRACE ThreadId(01) lambda_runtime: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/lambda_runtime-0.7.0/src/lib.rs:111: New event arrived (run loop)
2022-10-18T02:03:18.172244Z TRACE ThreadId(01) lambda_runtime: /home/taylor1791/.cargo/registry/src/github.com-1ecc6299db9ec823/lambda_runtime-0.7.0/src/lib.rs:200: Waiting for next event (incoming loop)

taylor1791 avatar Oct 18 '22 02:10 taylor1791

This is probably expected. Lambda runtimes are basically polling systems that request events from an API. In production, this only happens once at a time per sandbox, and different events will be distributed between many sandboxes. Locally, the runtime is constantly asking the emulator API for events, which is probably consuming that CPU. Suggestions for local improvements are very welcome.

calavera avatar Oct 18 '22 02:10 calavera

I did some poking around and I deeply understand what you mean by "Lambda runtimes are basically polling systems that request events from an API." The only thing I can think of to reduce CPU usage is to shutdown the cargo watch process after some period of inactivity. There is some nuance to such an implementation, but I believe it is possible. However, it is probably more effort than it is worth.

If you believe that the previous proposal is worthwhile or would like to hear other opinions from the community, feel free to leave this open. Otherwise, you can close this issue.

taylor1791 avatar Oct 18 '22 23:10 taylor1791

something that might give us more control over this is integrating directly with Watchexec, which powers cargo-watch: https://docs.rs/watchexec/latest/watchexec/ I looked at it when I implemented the watch subcommand, but it was pre-2.x version, and it didn't integrate very well with Tokio. I believe it might be possible now. That could also help with #180 but it might be a big rewrite.

calavera avatar Oct 19 '22 03:10 calavera

I am thrilled to see what #306 does for my battery life on a plane! Thank you :hugs:.

taylor1791 avatar Dec 08 '22 03:12 taylor1791