After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 723040 - UI frozen for about 20secs after connecting Nexus4 and switching it from PTP to MTP mode
UI frozen for about 20secs after connecting Nexus4 and switching it from PTP ...
Status: RESOLVED WONTFIX
Product: banshee
Classification: Other
Component: Device - MTP
git master
Other Linux
: Normal normal
: ---
Assigned To: Banshee Maintainers
Banshee Maintainers
gnome[unmaintained]
: 670915 (view as bug list)
Depends on:
Blocks:
 
 
Reported: 2014-01-26 18:12 UTC by Andrés G. Aragoneses (IRC: knocte)
Modified: 2020-03-17 09:56 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Stops banshee from attempting to unmount mtp devices (1.55 KB, patch)
2014-01-29 23:42 UTC, Nicholas Little
none Details | Review
Push the Unmap device call to the Scheduler as an IJob (2.52 KB, patch)
2014-02-02 16:34 UTC, Nicholas Little
none Details | Review

Description Andrés G. Aragoneses (IRC: knocte) 2014-01-26 18:12:42 UTC
1. Launched banshee.
2. Connected nexus4 via USB.
3. Switched nexus from PTP to MTP.

Expected results:
Should show contents of device. If it takes a bit to load them, it should show a progress bar, and never block the UI.

Current results:
Frozen for 20 secs (banshee turned "grey color"), then suddenly this was written in the console:

[1 Debug 19:07:34.434] Dap support extension loaded: Banshee.Dap.AppleDevice
[1 Debug 19:07:34.435] Dap support extension loaded: Banshee.Dap.Mtp
[1 Debug 19:07:34.447] Dap support extension loaded: Banshee.Dap.MassStorage
[1 Warn  19:07:34.448] Failed to load media-player-info file for 1
[1 Debug 19:07:34.452] Delayed Initializating Banshee.Daap.DaapService
[1 Debug 19:07:34.453] Delayed Initializating Banshee.Podcasting.PodcastService
[9 Debug 19:07:34.605] Refreshing any podcasts that haven't been updated in over an hour
Device 0 (VID=18d1 and PID=4ee1) is a Google Inc (for LG Electronics/Samsung) Nexus 4/10 (MTP).
Unable to open ~/.mtpz-data for reading, MTPZ disabled.Android device detected, assigning default bug flags
[1 Warn  19:07:34.721] Failed to load media-player-info file for 1
[1 Warn  19:07:34.725] Failed to load media-player-info file for 1
[13 Debug 19:07:35.940] DAAP Proxy listening for connections on port 8089
[7 Warn  19:07:56.325] Unable to get battery level from MTP device - Mtp.LibMtpException: Could not retrieve battery stats (in `Mtp')
  at Mtp.MtpDevice.GetBatteryLevel (Mtp.MtpDeviceHandle handle, System.UInt16& maxLevel, System.UInt16& currentLevel) [0x0001c] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Libraries/Mtp/Mtp/MtpDevice.cs:312 
  at Mtp.MtpDevice.get_BatteryLevel () [0x0000b] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Libraries/Mtp/Mtp/MtpDevice.cs:68 
  at Banshee.Dap.Mtp.MtpSource.DeviceInitialize (IDevice device) [0x00285] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Dap/Banshee.Dap.Mtp/Banshee.Dap.Mtp/MtpSource.cs:144 
[7 Debug 19:07:56.325] Found DAP support (Banshee.Dap.Mtp.MtpSource) for device Nexus 4 and Uuid /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2
[1 Debug 19:07:56.326] Unmapping DAP source (/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2)
[7 Info  19:07:56.326] AppleDeviceSource is ignoring unmounted volume Lenovo_Recovery
[7 Info  19:07:56.330] AppleDeviceSource is ignoring unmounted volume Windows8_OS
[7 Info  19:07:56.333] AppleDeviceSource is ignoring unmounted volume Nexus 4
Device 0 (VID=18d1 and PID=4ee1) is a Google Inc (for LG Electronics/Samsung) Nexus 4/10 (MTP).
ERROR: Could not close session!
ignoring libusb_claim_interface() = -6PTP_ERROR_IO: failed to open session, trying again after resetting USB interface
LIBMTP libusb: Attempt to reset device
inep: usb_get_endpoint_status(): Resource temporarily unavailable
outep: usb_get_endpoint_status(): Device or resource busy
usb_clear_halt() on IN endpoint: Device or resource busy
usb_clear_halt() on OUT endpoint: Device or resource busy
usb_clear_halt() on INTERRUPT endpoint: Device or resource busy
[15 Warn  19:07:56.504] Caught an exception - System.ObjectDisposedException: The object was used after being disposed. (in `mscorlib')
  at System.Runtime.InteropServices.SafeHandle.DangerousAddRef (System.Boolean& success) [0x00000] in <filename unknown>:0 
  at (wrapper managed-to-native) Mtp.Track:LIBMTP_Get_Tracklisting_With_Callback (Mtp.MtpDeviceHandle,Mtp.ProgressFunction,intptr)
  at Mtp.Track.GetTrackListing (Mtp.MtpDeviceHandle handle, Mtp.ProgressFunction function, IntPtr data) [0x00004] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Libraries/Mtp/Mtp/Track.cs:212 
  at Mtp.MtpDevice.GetAllTracks (Mtp.ProgressFunction callback) [0x00001] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Libraries/Mtp/Mtp/MtpDevice.cs:193 
  at Banshee.Dap.Mtp.MtpSource.LoadFromDevice () [0x00033] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Dap/Banshee.Dap.Mtp/Banshee.Dap.Mtp/MtpSource.cs:156 
[1 Debug 19:07:56.512] Finished - Startup Job
[1 Debug 19:07:56.518] Starting - Downloading Cover Art
[16 Debug 19:07:56.520] Finished - Downloading Cover Art
Android device detected, assigning default bug flags
[1 Debug 19:07:56.649] Creating Pango.Layout, configuring Cairo.Context
[1 Debug 19:07:56.689] Creating Pango.Layout, configuring Cairo.Context
[1 Warn  19:07:56.690] Buggy CSS theme: same background-color for .cell:selected and .cell
[1 Debug 19:07:56.695] Creating Pango.Layout, configuring Cairo.Context
[7 Warn  19:07:56.724] Unable to get battery level from MTP device - Mtp.LibMtpException: Could not retrieve battery stats (in `Mtp')
  at Mtp.MtpDevice.GetBatteryLevel (Mtp.MtpDeviceHandle handle, System.UInt16& maxLevel, System.UInt16& currentLevel) [0x0001c] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Libraries/Mtp/Mtp/MtpDevice.cs:312 
  at Mtp.MtpDevice.get_BatteryLevel () [0x0000b] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Libraries/Mtp/Mtp/MtpDevice.cs:68 
  at Banshee.Dap.Mtp.MtpSource.DeviceInitialize (IDevice device) [0x00285] in /home/knocte/Documents/Code/OpenSource/bansheeCLEANMANAGED/src/Dap/Banshee.Dap.Mtp/Banshee.Dap.Mtp/MtpSource.cs:144 
[7 Debug 19:07:56.724] Found DAP support (Banshee.Dap.Mtp.MtpSource) for device Nexus 4 and Uuid /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2
[7 Info  19:07:56.724] AppleDeviceSource is ignoring unmounted volume WINRE_DRV
Comment 1 Nicholas Little 2014-01-28 12:20:03 UTC
Hey, have you managed to do any troubleshooting with the nexus4?

It looks from the trace that libmtp might be failing to communicate with the device.

Without having banshee running, are you able to get useful information from mtp-detect, or mtp-filetree?

With the i9100, even though nautilus showed nothing I think I had to unmount the volume in the nautilus window before those commands worked.
Comment 2 Nicholas Little 2014-01-29 23:42:51 UTC
Created attachment 267599 [details] [review]
Stops banshee from attempting to unmount mtp devices

I tried to reproduce the issue you were experiencing and I think I got pretty close. I could get it to either freeze for a short period (less than two seconds) or forever (until I unplugged the device or switched its mode back to PTP)

I managed to get the latter case to occur fairly readily in the end, so hopefully we were seeing the same issue-the console log looks similar.

This patch sorts out the problem for me, it appears to be related to attempting to unmount the device. With this applied, I was able to switch the device between modes with little/no disruption to banshee's UI, and on selecting MTP the device is detected and displayed after a short period. Again, banshee is still responsive during that process. 

There's a major caveat though, when plugging the device in with MTP mode, I have to switch to PTP, then back again for the device to show up.

Banshee is already very well threaded with respect to device loading so I still can't put my finger on exactly _why_ the UI freeze occurs.

Hope this helps, at least in working out what's going wrong.
Comment 3 Andrés G. Aragoneses (IRC: knocte) 2014-01-30 00:01:51 UTC
Mm, I think that removing that is kind of risky.

I've read in a lot of places how fucked up is the fact that gphoto "holds" a connection to the device and it needs to be unmounted. Perhaps you can start reading this: http://banshee-media-player.2283330.n4.nabble.com/Bonus-Banshee-Bit-for-Nov-4th-2011-So-your-MTP-device-isn-t-showing-up-in-Banshee-td3991346.html (and go read especially the gphoto bug that is linked there... and that bug will lead you to another bug... etc etc all of them unresolved bugs...). So this is kind of a bumpy road...

On top of that, I think that maybe we shouldn't try to fix bugs in older systems that may happen to be system bugs (or MTP bugs). For example, I read this today: https://mail.gnome.org/archives/rhythmbox-devel/2014-January/msg00001.html which links to a PPA which says "13.10 (Saucy) and newer versions of Ubuntu contain all of these changes, so you don't need to use this ppa any more". So this leads me to think that I should upgrade my Ubuntu first of all. What version are you using BTW?
Comment 4 Andrés G. Aragoneses (IRC: knocte) 2014-01-30 00:03:11 UTC
(Forgot to say: I'm on Ubuntu 13.04)
Comment 5 Nicholas Little 2014-01-30 00:18:29 UTC
libgphoto2 - 2.5.2-r1
libmtp - 1.1.6

I think I read some similar reports when I was using a creative zen xtra quite a while ago now. That said, I can switch readily between the two modes with the patch applied, it's just the initial connection that doesn't work in MTP mode for me now.

I was hoping to see whether the patch has the same effect on your side. I'm not proposing this as a fix, but perhaps it'll get us some useful information about the issue.
Comment 6 Andrés G. Aragoneses (IRC: knocte) 2014-01-30 00:29:31 UTC
Ok I'll test it. So what distro and version are you on?
Comment 7 Nicholas Little 2014-01-30 00:37:20 UTC
I'm on gentoo, there's not really a version ;)
Comment 8 Andrés G. Aragoneses (IRC: knocte) 2014-02-02 15:47:21 UTC
Managed to reproduce this again, and I was fast enough to use kill -s QUIT <pidofbanshee>, and I got this for the main thread:

"Main Thread" tid=0x0x2ae90af93500 this=0x0x2ae90b084010 thread handle 0x403 state : waiting on 0x689 : Sem  owns ()
  at <unknown> <0xffffffff>
  at (wrapper managed-to-native) System.Threading.Monitor.try_enter_with_atomic_var (object,int,bool&) <IL 0x0000f, 0xffffffff>
  at System.Threading.Monitor.TryEnter (object,int,bool&) <IL 0x00044, 0x0005f>
  at System.Threading.Monitor.Enter (object,bool&) <IL 0x00003, 0x0003b>
  at (wrapper unknown) System.Threading.Monitor.FastMonitorEnterV4 (object,bool&) <IL 0x00059, 0xffffffff>
  at Banshee.Dap.DapService.UnmapDevice (string) [0x0000e] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Dap/Banshee.Dap/Banshee.Dap/DapService.cs:258
  at Banshee.Dap.DapService.OnHardwareDeviceRemoved (object,Banshee.Hardware.DeviceRemovedArgs) [0x00008] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Dap/Banshee.Dap/Banshee.Dap/DapService.cs:293
  at (wrapper delegate-invoke) <Module>.invoke_void__this___object_DeviceRemovedArgs (object,Banshee.Hardware.DeviceRemovedArgs) <IL 0x00059, 0xffffffff>
  at Banshee.Hardware.HardwareManager.OnDeviceRemoved (object,Banshee.Hardware.DeviceRemovedArgs) [0x0001f] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Core/Banshee.Services/Banshee.Hardware/HardwareManager.cs:194
  at Banshee.Hardware.Gio.HardwareManager.HandleManagerDeviceRemoved (object,Banshee.Hardware.Gio.MountArgs) [0x00024] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Backends/Banshee.Gio/Banshee.Hardware.Gio/HardwareManager.cs:60
  at Banshee.Hardware.Gio.Manager.VolumeRemoved (GLib.IVolume) [0x00069] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Backends/Banshee.Gio/Banshee.Hardware.Gio/LowLevel/Manager.cs:128
  at Banshee.Hardware.Gio.Manager.HandleMonitorMountRemoved (object,GLib.MountRemovedArgs) [0x0002c] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Backends/Banshee.Gio/Banshee.Hardware.Gio/LowLevel/Manager.cs:100
  at (wrapper runtime-invoke) <Module>.runtime_invoke_void__this___object_object (object,intptr,intptr,intptr) <IL 0x0005c, 0xffffffff>
  at <unknown> <0xffffffff>
  at (wrapper managed-to-native) System.Reflection.MonoMethod.InternalInvoke (System.Reflection.MonoMethod,object,object[],System.Exception&) <IL 0x0001c, 0xffffffff>
  at System.Reflection.MonoMethod.Invoke (object,System.Reflection.BindingFlags,System.Reflection.Binder,object[],System.Globalization.CultureInfo) <IL 0x0005a, 0x000e3>
  at System.Reflection.MethodBase.Invoke (object,object[]) <IL 0x00006, 0x00043>
  at System.Delegate.DynamicInvokeImpl (object[]) <IL 0x000dc, 0x0020b>
  at System.MulticastDelegate.DynamicInvokeImpl (object[]) <IL 0x0001a, 0x00047>
  at System.Delegate.DynamicInvoke (object[]) <IL 0x00002, 0x00033>
  at GLib.Signal.ClosureInvokedCB (object,GLib.ClosureInvokedArgs) [0x00039] in /home/knocte/Documents/Code/OpenSource/gtk-sharp/glib/Signal.cs:200
  at GLib.SignalClosure.Invoke (GLib.ClosureInvokedArgs) [0x00019] in /home/knocte/Documents/Code/OpenSource/gtk-sharp/glib/SignalClosure.cs:126
  at GLib.SignalClosure.MarshalCallback (intptr,intptr,uint,intptr,intptr,intptr) [0x0014c] in /home/knocte/Documents/Code/OpenSource/gtk-sharp/glib/SignalClosure.cs:167
  at (wrapper native-to-managed) GLib.SignalClosure.MarshalCallback (intptr,intptr,uint,intptr,intptr,intptr) <IL 0x00028, 0xffffffff>
  at <unknown> <0xffffffff>
  at (wrapper managed-to-native) Gtk.Application.gtk_main () <IL 0x0000e, 0xffffffff>
  at Gtk.Application.Run () [0x00001] in /home/knocte/Documents/Code/OpenSource/gtk-sharp/gtk/Application.cs:133
  at Banshee.Gui.GtkBaseClient.Run () [0x00019] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Core/Banshee.ThickClient/Banshee.Gui/GtkBaseClient.cs:225
  at Banshee.Gui.GtkBaseClient.Startup () [0x00010] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Core/Banshee.ThickClient/Banshee.Gui/GtkBaseClient.cs:79
  at Hyena.Gui.CleanRoomStartup.Startup (Hyena.Gui.CleanRoomStartup/StartupInvocationHandler) [0x00050] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Hyena/Hyena.Gui/Hyena.Gui/CleanRoomStartup.cs:54
  at Banshee.Gui.GtkBaseClient.Startup<T> () [0x00049] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Core/Banshee.ThickClient/Banshee.Gui/GtkBaseClient.cs:74
  at Banshee.Gui.GtkBaseClient.Startup<T> (string[]) [0x00021] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Core/Banshee.ThickClient/Banshee.Gui/GtkBaseClient.cs:64
  at Nereid.Client.Main (string[]) [0x00002] in /home/knocte/Documents/Code/OpenSource/banshee3NATIVE/src/Clients/Nereid/Nereid/Client.cs:54
  at (wrapper runtime-invoke) <Module>.runtime_invoke_void_object (object,intptr,intptr,intptr) <IL 0x00050, 0xffffffff>

So I guess the problem is that there is some MTP operation that is taking a long time and which is holding the lock that the main thread is trying to enter. We should probably launch a worker thread to unmap the device instead.
Comment 9 Nicholas Little 2014-02-02 16:34:13 UTC
Created attachment 267855 [details] [review]
Push the Unmap device call to the Scheduler as an IJob

Threaded like so?

Very astute, initial tests for me have my device and banshee playing together nicely even with automount enabled, banshee gracefully unmounts the device. I'm running with the patch I sent to you by email applied, but i'm pretty sure with nautilus' automount behaviour this should Just Work without even without that.
Comment 10 Andrés G. Aragoneses (IRC: knocte) 2014-02-02 16:48:33 UTC
Isn't it simpler to just us ThreadAssist.SpawnFromMain()? What would a job class offer as an advantage?
Comment 11 Nicholas Little 2014-02-02 16:55:45 UTC
Perhaps, but I thought mirroring the Map operation which uses a job class would be easier to maintain later, and passing that through the scheduler would ensure that "Happens Before/After" relationships are respected.
Comment 12 Andrés G. Aragoneses (IRC: knocte) 2014-02-03 13:28:15 UTC
(In reply to comment #11)
> Perhaps, but I thought mirroring the Map operation which uses a job class would

What's the map operation?

> be easier to maintain later, and passing that through the scheduler would
> ensure that "Happens Before/After" relationships are respected.

But we don't know why this call is so slow, the only thing we know is that it's kept waiting on the lock() statement, so wouldn't this fact mean that the scheduler would not matter here?
Comment 13 Nicholas Little 2014-02-03 15:18:28 UTC
(In reply to comment #12)
> (In reply to comment #11)
> > Perhaps, but I thought mirroring the Map operation which uses a job class would
> 
> What's the map operation?

private void MapDevice (IDevice device)
{
   Scheduler.Schedule (new MapDeviceJob (this, device));
}

I figured that having the UnmapDevice method follow the same pattern would be easier for people following us. 

I'm not sure that ThreadAssist.SpawnFromMain(() => { }); can be called a pattern ;)
 
> > be easier to maintain later, and passing that through the scheduler would
> > ensure that "Happens Before/After" relationships are respected.
> 
> But we don't know why this call is so slow, the only thing we know is that it's
> kept waiting on the lock() statement, so wouldn't this fact mean that the
> scheduler would not matter here?

Ok, from the stack trace the semaphore we're waiting on is DapService.sync.

A short analysis which I hope is about right:
When we plug our devices in, we're running a MapDevice job, and during that job we cause an UnmapDevice to occur indirectly when we run the Unmount command to allow us to take control of the MTP volume. But since the MapDevice job is on a different thread, we can't acquire the lock in UnmapDevice so we have to wait for all 5 MtpDevice.Connect() attempts to fail before UnmapDevice can acquire the lock.

You're probably right, in that the scheduler makes no difference with the current locking strategy. What I'm getting at here, is that if we use the scheduler then perhaps we can actually avoid the locks at a later date?
Comment 14 Andrés G. Aragoneses (IRC: knocte) 2014-02-03 18:34:07 UTC
(In reply to comment #13)
> (...) What I'm getting at here, is that if we use the
> scheduler then perhaps we can actually avoid the locks at a later date?

How? Can you elaborate on that?
Comment 15 Nicholas Little 2014-02-03 20:08:15 UTC
(In reply to comment #14)
> (In reply to comment #13)
> > (...) What I'm getting at here, is that if we use the
> > scheduler then perhaps we can actually avoid the locks at a later date?
> 
> How? Can you elaborate on that?

Looking at the Scheduler class, it's a priority queue of jobs which run consecutively, so if I do:

IJob job1 = new IJob() { },
     job2 = new IJob() { };

Scheduler.Schedule(job1);
Scheduler.Schedule(job2);

Then job1 will at least run before job2, which gives us the same relationship that the lock does and prevents both critical regions of code from running at the same time.

I may be wrong, I haven't tried it.
Comment 16 Ismael Olea 2014-02-04 22:54:08 UTC
Fedora 19 here:

libmtp-1.1.6-0.fc19.i686
libgphoto2-2.5.2-1.fc19.i686


I just can't access to any content with Banshee in my N4 :-m
Comment 17 Andrés G. Aragoneses (IRC: knocte) 2014-02-04 23:15:12 UTC
(In reply to comment #16)
> I just can't access to any content with Banshee in my N4 :-m

Ismael, please open a new bug for that, this one is about banshee getting frozen when connecting a Mtp device.

(In reply to comment #15)
> (In reply to comment #14)
> > (In reply to comment #13)
> > > (...) What I'm getting at here, is that if we use the
> > > scheduler then perhaps we can actually avoid the locks at a later date?
> > 
> > How? Can you elaborate on that?
> 
> Looking at the Scheduler class, it's a priority queue of jobs which run
> consecutively, so if I do...

Fair enough. However, your fix is a bit more sophisticated than what I'm proposing, and with more sophistication comes more risk. So what I decided to do is fix this for now with ThreadAssist[1], then backport the fix to the stable branch (because a 2.6.2 release is imminent), and then some days later (without the rush of a release), I will get your patch merged into master. So I'll leave the bug open for now.

[1] https://git.gnome.org/browse/banshee/commit/?id=b0e172f01374f807bf396b6a289e51f56f851e31
Comment 18 Andrés G. Aragoneses (IRC: knocte) 2014-02-05 18:48:55 UTC
*** Bug 670915 has been marked as a duplicate of this bug. ***
Comment 19 André Klapper 2020-03-17 09:56:09 UTC
Banshee is not under active development anymore and had its last code changes more than three years ago. Its codebase has been archived.

Closing this report as WONTFIX as part of Bugzilla Housekeeping to reflect
reality. Please feel free to reopen this ticket (or rather transfer the project
to GNOME Gitlab, as GNOME Bugzilla is being shut down) if anyone takes the
responsibility for active development again.
See https://gitlab.gnome.org/Infrastructure/Infrastructure/issues/264 for more info.