[tor-bugs] #25461 [Core Tor/Tor]: main event-loop spins consuming 100% of a CPU core running scheduler_set_channel_state
Tor Bug Tracker & Wiki
blackhole at torproject.org
Mon May 13 04:11:31 UTC 2019
#25461: main event-loop spins consuming 100% of a CPU core running
scheduler_set_channel_state
-------------------------------------------------+-------------------------
Reporter: Dhalgren | Owner: (none)
Type: defect | Status:
| assigned
Priority: High | Milestone: Tor:
| unspecified
Component: Core Tor/Tor | Version: Tor:
| 0.2.9.14
Severity: Normal | Resolution:
Keywords: performance, 034-roadmap-subtask, | Actual Points:
034-triage-20180328, 034-included-20180328 |
035-removed |
Parent ID: | Points:
Reviewer: | Sponsor:
-------------------------------------------------+-------------------------
Comment (by arma):
Ok, after another 50000 "PENDING to PENDING" iterations over the course of
a few minutes, it ended with:
{{{
May 13 00:01:28.160 [debug] scheduler_set_channel_state(): chan 1 changed
from scheduler state PENDING to PENDING
May 13 00:01:28.172 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.172 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.172 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 12 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found placeholder for circ_id
3947067420, channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
3947067420) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found placeholder for circ_id
2818402682, channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
2818402682) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 4026623635,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
4026623635) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 2645953702,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
2645953702) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 4058052004,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
4058052004) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 3540518513,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
3540518513) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 2616865552,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
2616865552) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.173 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.173 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 2831877474,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.173 [info] command_process_created_cell(): (circID
2831877474) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.173 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.173 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.173 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.174 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.174 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 2278004188,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.174 [info] command_process_created_cell(): (circID
2278004188) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.174 [debug] scheduler_evt_callback(): Scheduler event
callback called
May 13 00:01:28.174 [debug] update_socket_info(): chan=1 updated socket
info, limit: 7617, cwnd: 6, unacked: 6, notsent: 1071, mss: 1448
May 13 00:01:28.174 [debug] kist_scheduler_run(): Running the scheduler. 1
channels pending
May 13 00:01:28.174 [debug] outbuf_table_add(): scheduler init outbuf info
for chan=1
May 13 00:01:28.174 [debug] channel_write_packed_cell(): Writing
0x56003516f0a0 to channel 0x5600350d5bb0 with global ID 1
May 13 00:01:28.174 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found placeholder for circ_id
2818402682, channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.174 [debug] circuitmux_notify_xmit_destroy(): Cmux at
0x560034b67ef0 sent a destroy, cmux counter is now 2, global counter is
now 2
May 13 00:01:28.174 [debug] update_socket_written(): chan=1 wrote 543
bytes, old was 0
May 13 00:01:28.174 [debug] scheduler_set_channel_state(): chan 1 changed
from scheduler state PENDING to PENDING
May 13 00:01:28.174 [debug] channel_write_packed_cell(): Writing
0x56003516f0a0 to channel 0x5600350d5bb0 with global ID 1
May 13 00:01:28.174 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found placeholder for circ_id
3947067420, channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.174 [debug] circuitmux_notify_xmit_destroy(): Cmux at
0x560034b67ef0 sent a destroy, cmux counter is now 1, global counter is
now 1
May 13 00:01:28.174 [debug] update_socket_written(): chan=1 wrote 543
bytes, old was 543
May 13 00:01:28.174 [debug] scheduler_set_channel_state(): chan 1 changed
from scheduler state PENDING to PENDING
May 13 00:01:28.174 [debug] channel_write_packed_cell(): Writing
0x56003516f0a0 to channel 0x5600350d5bb0 with global ID 1
May 13 00:01:28.174 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found placeholder for circ_id
2349413837, channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.174 [debug] circuitmux_notify_xmit_destroy(): Cmux at
0x560034b67ef0 sent a destroy, cmux counter is now 0, global counter is
now 0
May 13 00:01:28.174 [debug] update_socket_written(): chan=1 wrote 543
bytes, old was 1086
May 13 00:01:28.174 [debug] scheduler_set_channel_state(): chan 1 changed
from scheduler state PENDING to WAITING_FOR_CELLS
May 13 00:01:28.174 [debug] channel_write_to_kernel(): Writing 1542 bytes
to kernel for chan 1
May 13 00:01:28.174 [debug] flush_chunk_tls(): flushed 1542 bytes, 0 ready
to flush, 0 remain.
May 13 00:01:28.174 [debug] connection_handle_write_impl(): After TLS
write of 1542: 0 read, 1571 written
May 13 00:01:28.174 [debug] free_outbuf_info_by_ent(): Freeing outbuf
table entry from chan=1
May 13 00:01:28.174 [debug] kist_scheduler_run(): len pending=0, len
to_readd=-1
May 13 00:01:28.174 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.174 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.174 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 3614737148,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.174 [info] command_process_created_cell(): (circID
3614737148) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.174 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): After TLS
read of 514: 543 read, 0 written
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 514 (0 pending in tls object).
May 13 00:01:28.174 [debug] channel_process_cell(): Processing incoming
cell_t 0x7ffe16cb2f50 for channel 0x5600350d5bb0 (global ID 1)
May 13 00:01:28.174 [debug] circuit_get_by_circid_channel_impl():
circuit_get_by_circid_channel_impl() found nothing for circ_id 3041944624,
channel ID 1 (0x5600350d5bb0)
May 13 00:01:28.174 [info] command_process_created_cell(): (circID
3041944624) unknown circ (probably got a destroy earlier). Dropping.
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
May 13 00:01:28.174 [debug] conn_read_callback(): socket 11 wants to read.
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): 11:
starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
May 13 00:01:28.174 [debug] tor_tls_read(): read returned r=-1, err=-2
May 13 00:01:28.174 [debug] connection_buf_read_from_socket(): After TLS
read of 0: 350 read, 0 written
May 13 00:01:28.174 [debug] connection_or_process_cells_from_inbuf(): 11:
starting, inbuf_datalen 0 (0 pending in tls object).
}}}
and then it got calmer again.
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/25461#comment:27>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list