Opened 10 years ago

Closed 10 years ago

#3861 closed Bug (fixed)

beachballs when downloading 4 torrents + verifying local data + adding a new torrent

Reported by: x190 Owned by: charles
Priority: Normal Milestone:
Component: libtransmission Version: 2.13+
Severity: Normal Keywords: [LAZY], timeChecked, Add
Cc:

Description (last modified by charles)

[LAZY] is too ambitious! All this work is done simply by opening a .torrent file to the "add window" stage, when in fact the user may decide to hit the "Cancel" button. Can this be delayed until after the "Add" button is pushed? Note also that the user may select only one or a handful of files from a torrent comprised of 100's or even a couple of thousand files. Why do the [LAZY] "timeChecked to now" thing for all the unwanted files? It does cause a GUI hang of several seconds (~15 sec.) depending on number of pieces involved.

"2010-12-29 19:09:34 -0700 utils.c:507 [Debug] Transmission: Couldn't read "/Users/-/Library/Application Support/Transmission/Resume/-.9a657f20f7a078a0.resume": No such file or directory
2010-12-29 19:09:34 -0700 resume.c:561 [Debug] -: Couldn't read "/Users/-/Library/Application Support/Transmission/Resume/-.9a657f20f7a078a0.resume"
2010-12-29 19:09:34 -0700 bencode.c:1720 [Info] Transmission: Saved "/Users/-/Library/Application Support/Transmission/Torrents/-.9a657f20f7a078a0.torrent"
2010-12-29 19:09:34 -0700 verify.c:257 [Info] -: Queued for verification
2010-12-29 19:09:34 -0700 verify.c:215 [Info] -: Verifying torrent
2010-12-29 19:09:34 -0700 verify.c:58 [Debug] -: verifying torrent...
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 0 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 1 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 2 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 3 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 4 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 5 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 6 timeChecked to now
2010-12-29 19:09:34 -0700 torrent.c:2322 [Debug] -: [LAZY] setting piece 7 timeChecked to now"

This one goes to 4480 pieces...

SL10.6.5 r11605

Attachments (3)

Trans_AM_Sample _while_NR.zip (52.9 KB) - added by x190 10 years ago.
Trans_Sample_%ofThread.zip (136.9 KB) - added by x190 10 years ago.
Screenshot_Shark_Report.jpg (244.4 KB) - added by x190 10 years ago.

Download all attachments as: .zip

Change History (30)

comment:1 Changed 10 years ago by charles

  • Description modified (diff)
  • Resolution set to worksforme
  • Status changed from new to closed
  • Summary changed from [LAZY] unnecessarily sets timeChecked to now for every piece before user hits "Add" button to pieces' timeChecked fields are set even before the user hits "Add" button
  • Version changed from 2.13+ to 2.13

x190, thanks for reporting this.

Here's what's happening: even in that Add window, the torrent starts being verified even before the user completes adding it. The verify process involves setting those flags. If we were to avoid that step, then we would have to verify a second time after the user hit the "Add" button. I understand your point about the conceptual model -- is it really a torrent yet before "Add" gets hit? -- but by doing it this way, we save effort by only doing it once.

As for the Debug message... that message will be removed before 2.20 goes final, but it's a Debug message, most people will never ever see them. I wish I hadn't removed the other lazy-verify messages so early just because people complained about their verbosity.

Also: moving this version back to 2.13 because we still set verify state fields before lazy-verify was introduced. The difference is that it's now a lot more prominent in the Debug messages... ;)

comment:2 Changed 10 years ago by x190

You really need to get a Mac, charles! :) First of all, I'm talking about adding a torrent for which I have no data via the "add window" which allows but does not demand a "Verify Local Data" i.e. a button must be selected. So all this activity by [LAZY], writing to .resume and .torrent, setting pieces etc. is totally unnecessary until, at least, the user hits the verify button, and even then if T finds 0 data, why waste system resources until the user commits to selecting "Add"?

I am unhappy with all the beachballing and I really hope T isn't trying to map out disk space (tell me that ain't true) for a freaking torrent I'm not even going to add or if I do I'll only select a file or two out of 1577.

comment:3 Changed 10 years ago by x190

  • Resolution worksforme deleted
  • Status changed from closed to reopened

comment:4 follow-up: Changed 10 years ago by charles

You really need to get a Mac, charles! :)

I promised myself 22 years ago I would never buy another piece of hardware from Apple, and I'm not going to start now. If you want to give me a Mac, that would be different. :)

I am unhappy with all the beachballing and I really hope T isn't trying to map out disk space (tell me that ain't true) for a freaking torrent I'm not even going to add or if I do I'll only select a file or two out of 1577.

Whoa whoa whoa! :) I find this ticket a little confusing and would like to try and understand this better. Setting the state fields described in the "[LAZY]" message is extremely fast, so at first I thought you were upset about the noise level of the Debug messages. But now you're talking about disk space allocation and beachballing, so now I'm not sure that I understand what problem you're seeing.

Is Transmission beachballing in the "add torrent" dialog?

If so, does the problem persist if you turn off Debug messages?

Thanks in advance for clarifying this.

Last edited 10 years ago by charles (previous) (diff)

comment:5 in reply to: ↑ 4 ; follow-ups: Changed 10 years ago by x190

Replying to charles:

You really need to get a Mac, charles! :)

I promised myself 22 years ago I would never buy another piece of hardware from Apple, and I'm not going to start now. If you want to give me a Mac, that would be different. :)

You have a standing offer for a Snow Leopard Install disc. :)

I am unhappy with all the beachballing and I really hope T isn't trying to map out disk space (tell me that ain't true) for a freaking torrent I'm not even going to add or if I do I'll only select a file or two out of 1577.

Whoa whoa whoa! :) I find this ticket a little confusing and would like to try and understand this better. Setting the state fields described in the "[LAZY]" message is extremely fast, so at first I thought you were upset about the noise level of the Debug messages. But now you're talking about disk space allocation and beachballing, so now I'm not sure that I understand what problem you're seeing.

Is Transmission beachballing in the "add torrent" dialog?

If so, does the problem persist if you turn off Debug messages?

Thanks in advance for clarifying this.

As I stated last night when I posted this ticket I was seeing beachballing for a good 15 seconds or more. This was with Add dialog open and was seen on mouse hover over the Message Log window and corresponded to the period when 1-4480 "setting piece" was being done. I'll need to do more testing as repeated testing with the same .torrent appears to do it's thing =<1 sec as I suppose it's finding it in memory? Also last night T was very busy with 4 other torrents. Will do more testing when I grab some new humongous .torrents.

Regarding "disk space allocation" I was only asking you to confirm this wasn't being done.

Last edited 10 years ago by x190 (previous) (diff)

comment:6 in reply to: ↑ 5 Changed 10 years ago by x190

Currently using r11609.

Last edited 10 years ago by x190 (previous) (diff)

comment:7 in reply to: ↑ 5 ; follow-up: Changed 10 years ago by livings124

Replying to x190:

You have a standing offer for a Snow Leopard Install disc. :) Can you set up a Hackintosh or VM of some kind?

We do not condone piracy or theft of software, period.

Last edited 10 years ago by livings124 (previous) (diff)

comment:8 in reply to: ↑ 7 Changed 10 years ago by x190

Replying to livings124:

Replying to x190:

You have a standing offer for a Snow Leopard Install disc. :)

We do not condone piracy or theft of software, period.

Huh? I was going to buy an in package copy from my local Apple Reseller and send it to him.

Last edited 10 years ago by x190 (previous) (diff)

comment:9 Changed 10 years ago by x190

charles,

This occurs when T is busy with a verification of data or just d/ling at high speed. So, I guess it's more of a queuing thing. The ball can spin for up to ~30 sec.

Last edited 10 years ago by x190 (previous) (diff)

comment:10 follow-up: Changed 10 years ago by charles

x190, is the disk busy during the ~30 seconds?

So has the "add torrent" portion of this ticket been dropped?

comment:11 in reply to: ↑ 10 ; follow-up: Changed 10 years ago by x190

Replying to charles:

x190, is the disk busy during the ~30 seconds?

How would I know exactly. Oh, Activity Monitor. :) I'm afraid I wasn't monitoring that.

So has the "add torrent" portion of this ticket been dropped?

Well, it still would be nice if we didn't insert ourselves into an already overloaded queue [my best guess] when there is still a 50/50 chance that the "cancel" button will be selected. Maybe you shouldn't have been so quick to brush jch aside when he offered help with threading. :)

'Nuff said. :)

Last edited 10 years ago by x190 (previous) (diff)

comment:12 in reply to: ↑ 11 Changed 10 years ago by charles

Replying to x190:

Replying to charles:

x190, is the disk busy during the ~30 seconds?

How would I know exactly.

...does OS X have a utility that you can use to watch CPU, bandwidth, and disk activity? That would be ideal.

So has the "add torrent" portion of this ticket been dropped?

Well, it still would be nice if we didn't insert ourselves into an already overloaded queue [my best guess] when there is still a 50/50 chance that the "cancel" button will be selected.

Maybe you shouldn't have been so quick to brush jch aside when he offered help with threading. :)

(this is off-topic, but I'll answer it parenthetically: libtransmission isn't threadsafe and will remain single-threaded. Likewise, the worker IO thread outlined in #1753 will exist as a single, nonterminating thread. jch didn't offer to help with #1753 -- he (very nicely) offered a threadpool module he'd written for another project. In my opinion, a threadpool module is unnecessary for a system consisting of two nonterminating threads.)

Anyway.

This ticket keeps throwing more topics into the mix, which makes it harder to diagnose the problem. Each additional topic multiplies -- not adds -- a ticket's complexity. So far we've discussed (1) beachballing, (2) JIT verification, (3) debug messages, (4) the add dialog, (5) fast downloads, (6) normal torrent verification, (7) mapping files on the disk, (8) queueing, and (9) a lack of threading.

To correctly diagnose the problem, we need to remove side-topics until only the essentials are left. We need the shortest, simplest list of conditions required to trigger the problem that you're seeing.

comment:13 Changed 10 years ago by charles

  • Summary changed from pieces' timeChecked fields are set even before the user hits "Add" button to Beachballing

comment:14 Changed 10 years ago by x190

Maybe not 'nuff yet! What a can of worms. I managed to get T into an Activity Monitor state of "Not Responding" testing this stuff. Was hitting 105% CPU at the time. Using r11614. 3 torrents d/ling. Request "Verify Local Data" on one. Course it's reading away at ~300 reads in/sec. Now open to add window that 1577 file test .torrent. Barber pole spins below the "Verify Data" button for about a minute (more or less), then after that, T spikes to over 100% CPU and that's when I got AM showing NR. Managed to get T quit via AM. Just a regular user requested "Verify Local Data" spikes CPU to 40% (r11614) whereas, in previous builds (~11605) I was only seeing ~25% CPU for the same operation.

Also, AM showed some crazy total for T CPU Time for a 4 and 1/2 hour period---~37+ hours? I've only got Core2Duo. (r11609 at that time).

comment:15 Changed 10 years ago by charles

It's very probable that the differences you're seeing are because you've got so much going on, rather than any changes to the code. For example you claim that "Verify Local Data" uses up to 40% of the CPU in r11614 but only used up to 25% in r11605. Let's take a look at the changes between those two versions:

r11614 changed a variable name in the source code
r11613 fixed the int memory leak in the "no pool" error
r11612 (no change to trunk)
r11611 (no change to trunk)
r11610 when announcing to a tracker, don't specify 0.0.0.0 as a local IPv4 address
r11609 change the text of an error message
r11608 adjust the status bar's color when inactive
r11607 work on the int memory leak in the "no pool" error
r11606 change the text of an error message

If you are convinced that your last report is accurate, please work your way through this list of changes via the mac builds kept at build.transmissionbt.com and find which of these commits caused "Verify Local Data" to nearly double its CPU use. ;)

To correctly diagnose the problem, we need to remove side-topics until only the essentials are left. We need the shortest, simplest list of conditions required to trigger the problem that you're seeing.

Last edited 10 years ago by charles (previous) (diff)

comment:16 Changed 10 years ago by x190

"It's very probable that the differences you're seeing are because you've got so much going on..."

Exactly! That's why I was suggesting keeping not yet added torrents out of the mix until absolutely necessary and after all this testing I'd say for sure they need to be queued somehow if another verification is going on. After all you wouldn't allow more than one already loaded torrent to be verified at one time.

Steps to reproduce:

#1 Load up at least 3 or 4 large torrents (mine were 68GB +34GB +1GB +.7GB)

#2 D/l at least a couple of GB for at least one of these torrents to have something to verify on a user request.

#3 Find yourself a .torrent that's a healthy size and has lots of files and pieces. (mine was 5GB, 1600 files, 4500 pieces)

#4 Get everything d/ling at a healthy speed.

#5 Pause the torrent that has downloaded ~2 GB and request a verify.

#6 Immediately, open the .torrent to the add window.

That should about do it. Repeat #5 and #6 if necessary.

Last edited 10 years ago by x190 (previous) (diff)

comment:17 follow-up: Changed 10 years ago by charles

Please generate a shark report of the beachballing so that we can see where Transmission is hanging.

comment:18 in reply to: ↑ 17 Changed 10 years ago by x190

Replying to charles:

Please generate a shark report of the beachballing so that we can see where Transmission is hanging.

This should be fairly easy to replicate by queuing a couple of user requested "Verify Local Data" requests and d/ling to a couple of others and then trying to add 1 or more new .torrents. The regular d/ling process and verification by [LAZY] plus associated logging already causes considerable CPU spikes so it's not hard to imagine that adding all data verifications and setting up verify fields for new torrents to the mix might cause a malfunction at the junction.

Not sure about the shark report as me and my 'puter are feeling a bit stressed out right now. :)

Have a great 2011!

comment:19 Changed 10 years ago by charles

I can't run this test or generate a shark report because I don't have a mac.

We've been cycling through a lot of tickets together recently so I can understand why you might be feeling a little frustrated right now. Later on, things have cooled down and you have some more free time, I'd be grateful if you gave the shark report a try. Thanks.

Last edited 10 years ago by charles (previous) (diff)

comment:20 Changed 10 years ago by charles

  • Summary changed from Beachballing to beachballs when downloading 4 torrents + verifying local data + adding a new torrent

Changed 10 years ago by x190

comment:21 Changed 10 years ago by x190

Testing with 4 d/ls @ ~500KB, one verification (~1.5GB), no adding of new torrents. CPU goes to 125% then shows Not Responding (and GUI beachballs) until verification ends.

Please advise whether Activity Monitor info is sufficient, Mr. Lee??? :)

Last edited 10 years ago by x190 (previous) (diff)

comment:22 Changed 10 years ago by x190

Hmm... Guess all those files I attached look the same because the selection has to be made before the sample is taken? Which one do you need or do I have to figure out how to use Shark?

Changed 10 years ago by x190

comment:23 Changed 10 years ago by x190

Testing with r11625. Problem seems related to GUI (Message Log Window) possibly combined with debug logging. My second attachment is a sample taken during All Data Verification for 1 torrent with only 1 other d/ling at low speed. Verification completes normally but uses high CPU (50-125%). Also, I noticed that the Message Log Window is unscrollable for a few minutes after verification is complete. If you use click to here on the ML scroll bar it spikes the CPU to 100%. Eventually, (perhaps 2-3 minutes later) normal GUI operation returns.

Last edited 10 years ago by x190 (previous) (diff)

Changed 10 years ago by x190

comment:24 Changed 10 years ago by x190

Shark Report as requested. Generated while app NR during user requested data verification. 1 other low speed d/l.http://transmission.pastebin.com/Fk284W7c

comment:25 Changed 10 years ago by livings124

x190: give r11631 a try

comment:26 Changed 10 years ago by x190

All issues appear to have been addressed. Thank you! I did see a top use of just under 50% CPU during testing (r11640), but that is quite manageable for my system. Most of the time, during a user-requested verification of all data it cruised along at ~35% CPU which is comparable to 2.13 release. Since you are now queuing new torrents during a local data verification perhaps a drop-down explanation dialog for those who use the add window detailing why the user is seeing the spinning barber pole and informing them that the torrent will be queued when added would be helpful.

comment:27 Changed 10 years ago by jordan

  • Milestone None Set deleted
  • Resolution set to fixed
  • Status changed from reopened to closed
  • Version changed from 2.13 to 2.13+

Thank you for retesting this and for the shark reports!

As for the drop-down dialog, I think that would probably confuse most new users :)

Note: See TracTickets for help on using tickets.