[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

Re: [tor-bugs] #25461 [Core Tor/Tor]: main event-loop spins consuming 100% of a CPU core running scheduler_set_channel_state

To: undisclosed-recipients: ;
Subject: Re: [tor-bugs] #25461 [Core Tor/Tor]: main event-loop spins consuming 100% of a CPU core running scheduler_set_channel_state
From: "Tor Bug Tracker & Wiki" <blackhole@xxxxxxxxxxxxxx>
Date: Mon, 13 May 2019 04:11:31 -0000
Auto-submitted: auto-generated
Delivered-to: archiver@xxxxxxxx
Delivery-date: Mon, 13 May 2019 00:11:41 -0400
In-reply-to: <048.9af1542a86c255997dead02c914d05a6@torproject.org>
List-archive: <http://lists.torproject.org/pipermail/tor-bugs/>
List-help: <mailto:tor-bugs-request@lists.torproject.org?subject=help>
List-id: "auto: Tor bug tracker status mails" <tor-bugs.lists.torproject.org>
List-post: <mailto:tor-bugs@lists.torproject.org>
List-subscribe: <https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=subscribe>
List-unsubscribe: <https://lists.torproject.org/cgi-bin/mailman/options/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=unsubscribe>
References: <048.9af1542a86c255997dead02c914d05a6@torproject.org>
Reply-to: no-reply@xxxxxxxxxxxxxx, tor-assistants@xxxxxxxxxxxxxx
Sender: "tor-bugs" <tor-bugs-bounces@xxxxxxxxxxxxxxxxxxxx>

#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

_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

Prev by Author: Re: [tor-bugs] #30388 [Applications/Tor Browser]: NoScript and all user-installed add-ons got deactivated! (armagadd-on-2.0)
Next by Author: [tor-bugs] #30683 [Applications/Tor Browser]: Properties in dom/locales/$lang/chrome/ allow detecting user locale
Previous by thread: Re: [tor-bugs] #25461 [Core Tor/Tor]: main event-loop spins consuming 100% of a CPU core running scheduler_set_channel_state
Next by thread: [tor-bugs] #30488 [Applications/Tor Browser]: Update TOPL library to Commit e29acfb25f
Index(es):
- Author
- Thread