search

beetbox / beets

music library manager and MusicBrainz tagger
http://beets.io/
MIT License
12.73k stars 1.82k forks source link

Beets is extremely slow, futex connection time outs #3642

Closed lovesegfault closed 4 years ago

lovesegfault commented 4 years ago

Problem

Beets has been extremely slow for me, when I investigate with strace I see thousands of these:

futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321605, tv_nsec=417935000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321606, tv_nsec=418050000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321607, tv_nsec=418223000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321608, tv_nsec=418410000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321609, tv_nsec=418594000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321610, tv_nsec=418774000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321611, tv_nsec=418958000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321612, tv_nsec=419091000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321613, tv_nsec=419262000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321614, tv_nsec=419467000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321615, tv_nsec=419617000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321616, tv_nsec=419823000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321617, tv_nsec=419974000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321618, tv_nsec=420146000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7f1d30000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593321619, tv_nsec=420260000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)

This is triggered when importing any FLAC albums. I haven't tested importing other formats.

Setup

My configuration (output of beet config) is:

absubmit:
  auto: true
  extractor: >-
    /nix/store/7bn72r9nycmi6fjklgmkpz88fa5a76r5-essentia-extractor-2.1_beta2/bin/streaming_extractor_music
acoustid:
  apikey: u3HtJQTYY1
art_filename: cover
asciify_paths: false
clutter:
  - Thumbs.DB
  - .DS_Store
directory: /srv/music
embedart:
  auto: true
fetchart:
  auto: true
  cautious: false
  enforce_ratio: 10%
  maxwidth: 2000
  minwidth: 900
  sources: filesystem fanarttv *
format_album: $albumartist - $album
format_item: $artist - $album - $title
format_raw_length: false
id3v23: false
ignore:
  - .*
  - '*~'
  - System Volume Information
  - lost+found
ignore_hidden: true
import:
  autotag: true
  bell: true
  copy: true
  default_action: apply
  delete: false
  detail: true
  duplicate_action: ask
  flat: false
  from_scratch: true
  group_albums: false
  hardlink: false
  incremental: true
  languages:
    - en
  link: false
  log: /home/bemeurer/.local/share/beets.log
  move: true
  none_rec_action: ask
  pretend: false
  quiet: false
  quiet_fallback: skip
  resume: ask
  search_ids: []
  set_fields: {}
  singletons: false
  timid: true
  write: true
lastgenre:
  auto: true
  canonical: true
  fallback: ''
library: /srv/music/library.db
lyrics:
  auto: true
  fallback: ''
match:
  distance_weights:
    album: 3
    album_id: 5
    albumdisambig: 0.5
    artist: 3
    catalognum: 0.5
    country: 0.5
    label: 0.5
    media: 1
    mediums: 1
    missing_tracks: 0.9
    source: 2
    track_artist: 2
    track_id: 5
    track_index: 1
    track_length: 2
    track_title: 3
    tracks: 2
    unmatched_tracks: 0.6
    year: 1
  ignored: []
  max_rec:
    missing_tracks: medium
    unmatched_tracks: medium
  medium_rec_thresh: 0.25
  preferred:
    countries:
      - US
      - GB|UK
    media:
      - Digital Media|File
      - CD
    original_year: true
  rec_gap_thresh: 0.25
  required: []
  strong_rec_thresh: 0.04
  track_length_grace: 10
  track_length_max: 30
max_filename_length: 0
musicbrainz:
  host: musicbrainz.org
  ratelimit: 1
  ratelimit_interval: 1
  searchlimit: 5
original_date: true
path_sep_replace: _
paths:
  comp: 'Various Artists/$album%aunique{}/$disc.$track $title'
  default: '$albumartist/$album%aunique{}/$disc.$track $title'
per_disc_numbering: true
pluginpath: []
plugins:
  - absubmit
  - acousticbrainz
  - badfiles
  - chroma
  - edit
  - embedart
  - fetchart
  - fromfilename
  - info
  - lastgenre
  - lyrics
  - mbsync
  - missing
  - scrub
replace:
  '[<>:"\?\*\|]': _
  '[\\/]': _
  '[\x00-\x1f]': _
  \.$: _
  \s+$: ''
  ^-: _
  ^\.: _
  ^\s+: ''
sort_album: albumartist+ album+
sort_case_insensitive: true
sort_item: artist+ album+ disc+ track+
statefile: state.pickle
threaded: true
time_format: '%Y-%m-%d %H:%M:%S'
timeout: 5
ui:
  color: true
  colors:
    action: blue
    action_default: turquoise
    text_error: red
    text_highlight: red
    text_highlight_minor: lightgray
    text_success: green
    text_warning: yellow
  length_diff_thresh: 10
  terminal_width: 120
va_name: Various Artists
verbose: 0
lovesegfault commented 4 years ago

I can reproduce this on master

sampsyo commented 4 years ago

Hi! Could you please try the investigative steps that the template suggests: namely, running in verbose mode and disabling plugins?

I'm afraid an ETIMEDOUT on futex calls is not very informative by itself. The underlying cause is likely a long-latency IO operation, but the synchronization by itself does not indicate what.

lovesegfault commented 4 years ago

Alright, this is with all plugins disabled:

viins ❯ beet -vvv import --from-scratch --noincremental -c Hubert\ Laws\ -\ Afro-Classic\ -\ 1970-2017\ \(24-192\)
user configuration: /home/bemeurer/.config/beets/config.yaml
data directory: /home/bemeurer/.config/beets
plugin paths:
Sending event: pluginload
library database: /srv/music/library.db
library directory: /srv/music
Sending event: library_opened
Sending event: import_begin
Sending event: import_task_created
Sending event: import_task_start
Looking up: /home/bemeurer/tmp/beet/Hubert Laws - Afro-Classic - 1970-2017 (24-192)
Tagging Hubert Laws - Afro-Classic
No album ID found.
Search terms: Hubert Laws - Afro-Classic
Album might be VA: False
Searching for MusicBrainz releases with: {'release': 'afro-classic', 'artist': 'hubert laws', 'tracks': '5'}
Requesting MusicBrainz release dfc9a9be-6490-4f3c-965e-3ab550ac8339
primary MB release type: album
Sending event: albuminfo_received
Candidate: Hubert Laws - Afro-Classic (dfc9a9be-6490-4f3c-965e-3ab550ac8339)
Computing track assignment...
...done.
Success. Distance: 0.00
Requesting MusicBrainz release d0a965d8-ad77-482e-9be7-4b8939594234
primary MB release type: album
Sending event: albuminfo_received
Candidate: Hubert Laws - Afro-Classic (d0a965d8-ad77-482e-9be7-4b8939594234)
Computing track assignment...
...done.
Success. Distance: 0.06
Requesting MusicBrainz release 76e0f284-600b-3d02-8798-d3eb020d439e
primary MB release type: album
Sending event: albuminfo_received
Candidate: Hubert Laws - The Rite of Spring (76e0f284-600b-3d02-8798-d3eb020d439e)
Computing track assignment...
...done.
Success. Distance: 0.57
Requesting MusicBrainz release f458053e-b509-4705-91f7-fa0f79e9fd5b
primary MB release type: album
Sending event: albuminfo_received
Candidate: Hubert Laws - The Rite of Spring (f458053e-b509-4705-91f7-fa0f79e9fd5b)
Computing track assignment...
...done.
Success. Distance: 0.56
Requesting MusicBrainz release bc765109-fa15-4e52-a780-93ca0309706c
primary MB release type: album
Sending event: albuminfo_received
Candidate: Hubert Laws - Say It With Silence (bc765109-fa15-4e52-a780-93ca0309706c)
Computing track assignment...
...done.
Success. Distance: 0.58
Evaluating 5 candidates.

/home/bemeurer/tmp/beet/Hubert Laws - Afro-Classic - 1970-2017 (24-192) (5 items)
Sending event: before_choose_candidate
Tagging:
    Hubert Laws - Afro-Classic
URL:
    https://musicbrainz.org/release/dfc9a9be-6490-4f3c-965e-3ab550ac8339
(Similarity: 100.0%) (1970)
 * Fire and Rain
 * Allegro from Concerto No. 3 in D
 * Theme from Love Story
 * Passacaglia in C Minor           -> Passacaglia in C minor
 * Flute Sonata in F
[A]pply, More candidates, Skip, Use as-is, as Tracks, Group albums,
Enter search, enter Id, aBort?

By this point I am already getting the futex ETIMEDOUT in strace:

viins ❯ strace -p $(ps aux | rg beet | fzf | cut -f 3 -d ' ')
strace: Process 9613 attached
restart_syscall(<... resuming interrupted read ...>) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372039, tv_nsec=192633000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372040, tv_nsec=192823000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372041, tv_nsec=192939000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372042, tv_nsec=193131000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372043, tv_nsec=193333000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372044, tv_nsec=193461000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372045, tv_nsec=193653000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372046, tv_nsec=193839000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372047, tv_nsec=194016000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372048, tv_nsec=194164000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372049, tv_nsec=194381000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372050, tv_nsec=194566000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372051, tv_nsec=194735000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372052, tv_nsec=194891000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372053, tv_nsec=195046000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372054, tv_nsec=195282000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372055, tv_nsec=195481000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372056, tv_nsec=195640000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372057, tv_nsec=195838000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372058, tv_nsec=196028000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372059, tv_nsec=196185000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372060, tv_nsec=196312000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372061, tv_nsec=196472000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372062, tv_nsec=196592000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372063, tv_nsec=196746000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372064, tv_nsec=196961000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372065, tv_nsec=197142000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372066, tv_nsec=197300000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372067, tv_nsec=197456000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372068, tv_nsec=197568000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372069, tv_nsec=197713000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372070, tv_nsec=197926000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372071, tv_nsec=198137000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372072, tv_nsec=198288000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372073, tv_nsec=198495000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372074, tv_nsec=198662000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372075, tv_nsec=198807000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372076, tv_nsec=199027000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372077, tv_nsec=199202000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fc44c000b60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1593372078, tv_nsec=199351000}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)

If I continue it works fine, without taking (literally) hours.

I then slowly enabled plugins, and I now think chroma is to blame. It causes the process to get stuck here:

found duplicates: [1058]
default action for duplicates: a
This album is already in the library!
Old: 5 items, FLAC, 5367kbps, 37:58, 1.4 GiB
New: 5 items, FLAC, 5367kbps, 37:58, 1.4 GiB
[S]kip new, Keep both, Remove old, Merge all? r
Sending event: import_task_apply
0 of 5 items replaced
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
Sending event: database_change
removing 5 old duplicated items
Sending event: database_change
Sending event: item_removed
deleting duplicate /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac
Sending event: database_change
Sending event: item_removed
deleting duplicate /srv/music/Hubert Laws/Afro-Classic/01.02 Allegro from Concerto No. 3 in D.flac
Sending event: database_change
Sending event: item_removed
deleting duplicate /srv/music/Hubert Laws/Afro-Classic/01.03 Theme from Love Story.flac
Sending event: database_change
Sending event: item_removed
deleting duplicate /srv/music/Hubert Laws/Afro-Classic/01.04 Passacaglia in C minor.flac
Sending event: database_change
Sending event: database_change
Sending event: item_removed
deleting duplicate /srv/music/Hubert Laws/Afro-Classic/01.05 Flute Sonata in F.flac
Sending event: item_copied
Sending event: database_change
Sending event: database_change
Sending event: write

And creates the ETIMEDOUT "storm": 

futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=756318034}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=761388736}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=766484209}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=771643862}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=776786546}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=781886566}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
futex(0x7fb5ae38dd90, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7fb5ae38dd88, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=264215, tv_nsec=786982783}, FUTEX_BITSET_MATCH_ANY) = -1 ETIMEDOUT (Connection timed out)
lovesegfault commented 4 years ago

The scrub plugin also causes the issue.

If I remove chroma and scrub from my plugin list beets works normally.

sampsyo commented 4 years ago

Well, the chroma plugin calculates acoustic fingerprints for every track, which necessarily takes a long time… and scrub involves extra I/O to rewrite the data on the tracks. It seems normal to me that these things would take extra time.

I don't think it's clear that there's a central issue they have in common—nor that the strace output is pointing at a particular issue other than that certain tasks are taking a long time, so synchronization in the pipeline is forced to wait. I'm sorry I can't be more helpful with just this output, but maybe it's worth trying to narrow down exactly that is taking a long time for specific albums?

lovesegfault commented 4 years ago

I wonder whether the way scrub access the files is making ZFS not happy.

I disabled auto scrubbing, and ran a manual scrub instead. Even though I'm on a fast NVME SSD it's still, VERY slow, in the order of a minute per track. I don't fully understand why this would be the case, however.

lovesegfault commented 4 years ago

Does beets have a discord or other non-async chat medium? I think it'd be easier to show what is happening with a tmate session. The logs don't fully convey what's going on.

lovesegfault commented 4 years ago

Alright, this is me stracing but filtering out futex syscalls:

[pid 30804] 13:22:28 openat(AT_FDCWD, "/srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac", O_RDONLY|O_CLOEXEC) = 10 <0.000010>
[pid 30804] 13:22:28 fstat(10, {st_mode=S_IFREG|0644, st_size=326216061, ...}) = 0 <0.000006>
[pid 30804] 13:22:28 ioctl(10, TCGETS, 0x7f05b4eb9480) = -1 ENOTTY (Inappropriate ioctl for device) <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 0 <0.000005>
[pid 30804] 13:22:28 read(10, "fLaC\0\0\0\"\20\0\20\0\0\0\20\0>\354.\340\3p\5~.\3204\362S$F\10"..., 131072) = 131072 <0.000013>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000005>
[pid 30804] 13:22:28 read(10, "FR(\373PI\6\252\361\361v\217\326Y\363\235w\326~O\301\332\214yvgf\f\2427\254\242"..., 262144) = 262144 <0.000026>
[pid 30804] 13:22:28 read(10, "%\10\351\327\332]\211U\263[\226\203\233\315yb\2452\325k,\326\32\361\334\0022\226\312uY\334"..., 131072) = 131072 <0.000016>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 524288 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 524288 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_END) = 326216061 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 326216061 <0.000005>
[pid 30804] 13:22:28 close(10)          = 0 <0.000006>
[pid 30804] 13:22:28 openat(AT_FDCWD, "/srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac", O_RDWR|O_CLOEXEC) = 10 <0.000009>
[pid 30804] 13:22:28 fstat(10, {st_mode=S_IFREG|0644, st_size=326216061, ...}) = 0 <0.000006>
[pid 30804] 13:22:28 ioctl(10, TCGETS, 0x7f05b4eb9940) = -1 ENOTTY (Inappropriate ioctl for device) <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 0 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 0 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 0 <0.000005>
[pid 30804] 13:22:28 read(10, "fLaC\0\0\0\"\20\0\20\0\0\0\20\0>\354.\340\3p\5~.\3204\362S$F\10"..., 131072) = 131072 <0.000013>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 131072 <0.000005>
[pid 30804] 13:22:28 read(10, "FR(\373PI\6\252\361\361v\217\326Y\363\235w\326~O\301\332\214yvgf\f\2427\254\242"..., 262144) = 262144 <0.000024>
[pid 30804] 13:22:28 read(10, "%\10\351\327\332]\211U\263[\226\203\233\315yb\2452\325k,\326\32\361\334\0022\226\312uY\334"..., 131072) = 131072 <0.000014>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 524288 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 524288 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_END) = 326216061 <0.000007>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 326216061 <0.000005>
[pid 30804] 13:22:28 lseek(10, 450598, SEEK_SET) = 450598 <0.000005>
[pid 30804] 13:22:28 mprotect(0x7f059c431000, 442368, PROT_READ|PROT_WRITE) = 0 <0.000010>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_END) = 326216061 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 326216061 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_END) = 326216061 <0.000006>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 326216061 <0.000005>
[pid 30804] 13:22:28 lseek(10, 0, SEEK_CUR) = 326216061 <0.000005>
[pid 30804] 13:22:28 fstat(10, {st_mode=S_IFREG|0644, st_size=326216061, ...}) = 0 <0.000006>
[pid 30804] 13:22:28 fcntl(10, F_DUPFD_CLOEXEC, 0) = 11 <0.000005>
[pid 30804] 13:22:28 mmap(NULL, 325773693, PROT_READ|PROT_WRITE, MAP_SHARED, 10, 0x6c000) = 0x7f0584951000 <0.000009>
[pid 30804] 13:29:25 close(11)          = 0 <0.000006>
[pid 30804] 13:29:25 munmap(0x7f0584951000, 325773693) = 0 <0.012893>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_END) = 326216061 <0.000010>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_CUR) = 326216061 <0.000006>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_CUR) = 326216061 <0.000006>
[pid 30804] 13:29:25 ftruncate(10, 326211609) = 0 <0.000056>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_CUR) = 326216061 <0.000006>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_SET) = 0 <0.000006>
[pid 30804] 13:29:25 write(10, "fLaC", 4) = 4 <0.000053>
[pid 30804] 13:29:25 write(10, "\0\0\0\"\20\0\20\0\0\0\20\0>\354.\340\3p\5~.\3204\362S$F\10\312\256NY"..., 446142) = 446142 <0.000246>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_CUR) = 446146 <0.000007>
[pid 30804] 13:29:25 close(10)          = 0 <0.000009>
[pid 30804] 13:29:25 openat(AT_FDCWD, "/srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac", O_RDONLY|O_CLOEXEC) = 10 <0.000020>
[pid 30804] 13:29:25 fstat(10, {st_mode=S_IFREG|0644, st_size=326211609, ...}) = 0 <0.000007>
[pid 30804] 13:29:25 ioctl(10, TCGETS, 0x7f05b4eb9760) = -1 ENOTTY (Inappropriate ioctl for device) <0.000008>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_CUR) = 0 <0.000019>
[pid 30804] 13:29:25 read(10, "fLaC\0\0\0\"\20\0\20\0\0\0\20\0>\354.\340\3p\5~.\3204\362S$F\10"..., 131072) = 131072 <0.000049>
[pid 30804] 13:29:25 lseek(10, 0, SEEK_CUR) = 131072 <0.000019>
[pid 30804] 13:29:25 lseek(10, -131, SEEK_END) = 326211478 <0.000008>
[pid 30804] 13:29:25 read(10, "\0\333A\377\370\303\34\345\237\234\263\0\0\0\0\0\0\0\0\2\310\377\370\303\34\345\237\235\264\0\0\0"..., 131072) = 131 <0.000009>

If you look at these lines: 

[pid 30804] 13:22:28 mmap(NULL, 325773693, PROT_READ|PROT_WRITE, MAP_SHARED, 10, 0x6c000) = 0x7f0584951000 <0.000009>
[pid 30804] 13:29:25 close(11)          = 0 <0.000006>

You can see it took seven minutes to perform that

lovesegfault commented 4 years ago

And again, further down the strace logs you have the same combo taking a total of 10 minutes

[pid 30804] 13:29:25 mmap(NULL, 326097472, PROT_READ|PROT_WRITE, MAP_SHARED, 10, 0x6c000) = 0x7f0584902000 <0.000017>
[pid 30804] 13:39:01 close(11)          = 0 <0.000011>
[pid 30804] 13:39:01 munmap(0x7f0584902000, 326097472) = 0 <0.020770>

strace: https://gist.github.com/lovesegfault/2841fc6c994badfeb3d110d0da4363d4

sampsyo commented 4 years ago

That is pretty slow! The strace still doesn't make it very clear where this is coming from, however. If the logging by itself (as well as running commands like beet scrub in isolation) is not enough to pin down exactly what step is taking so long, perhaps some good old-fashioned print-debugging could help?

We do also have a Gitter instance for development discussion, but I'm not sure if interactive debugging will be the most productive here.

lovesegfault commented 4 years ago

I've tracked this down to this portion of code in the scrub plugin:

    def _scrub(self, path):
        """Remove all tags from a file.
        """
        for cls in self._mutagen_classes():
            self._log.debug(u'scrubbing {}', cls )
            # Try opening the file with this type, but just skip in the
            # event of any error.
            try:
                self._log.debug(u'opening {} as {}', path, cls )
                f = cls(util.syspath(path))
                self._log.debug(u'opened {} as {}', path, cls )
            except Exception:
                self._log.debug(u'failed to open {} with type {}', path, cls)
                continue
            if f.tags is None:
                self._log.debug(u'tags empty for {} with type {}', path, cls)
                continue

            # Remove the tag for this type.
            try:
                self._log.debug(u'scrubbing {}', cls)
                f.delete()
                self._log.debug(u'scrubbed {}', cls)
            except NotImplementedError:
                # Some Mutagen metadata subclasses (namely, ASFTag) do not
                # support .delete(), presumably because it is impossible to
                # remove them. In this case, we just remove all the tags.
                for tag in f.keys():
                    del f[tag]
                f.save()
                self._log.debug(u'nuked all tags {}', path)
            except (IOError, mutagen.MutagenError) as exc:
                self._log.error(u'could not scrub {0}: {1}',
                                util.displayable_path(path), exc)

In this particular section

                self._log.debug(u'scrubbing {}', cls)
                f.delete()
                self._log.debug(u'scrubbed {}', cls)

Relevant logs:

scrub: auto-scrubbing /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac
scrub: restore was true
scrub: saved image
scrub: scrubbing <class 'mutagen.asf.ASF'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.asf.ASF'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.asf.ASF'>
scrub: scrubbing <class 'mutagen.apev2.APEv2File'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.apev2.APEv2File'>
scrub: opened /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.apev2.APEv2File'>
scrub: tags empty for /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.apev2.APEv2File'>
scrub: scrubbing <class 'mutagen.flac.FLAC'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.flac.FLAC'>
scrub: opened /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.flac.FLAC'>
scrub: scrubbing <class 'mutagen.flac.FLAC'> >>>>>GETS STUCK<<<<<
scrub: scrubbed <class 'mutagen.flac.FLAC'>
scrub: scrubbing <class 'mutagen.id3.ID3FileType'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.id3.ID3FileType'>
scrub: opened /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.id3.ID3FileType'>
scrub: tags empty for /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.id3.ID3FileType'>
scrub: scrubbing <class 'mutagen.mp3.MP3'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.mp3.MP3'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.mp3.MP3'>
scrub: scrubbing <class 'mutagen.mp4.MP4'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.mp4.MP4'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.mp4.MP4'>
scrub: scrubbing <class 'mutagen.oggflac.OggFLAC'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.oggflac.OggFLAC'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.oggflac.OggFLAC'>
scrub: scrubbing <class 'mutagen.oggspeex.OggSpeex'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.oggspeex.OggSpeex'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.oggspeex.OggSpeex'>
scrub: scrubbing <class 'mutagen.oggtheora.OggTheora'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.oggtheora.OggTheora'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.oggtheora.OggTheora'>
scrub: scrubbing <class 'mutagen.oggvorbis.OggVorbis'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.oggvorbis.OggVorbis'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.oggvorbis.OggVorbis'>
scrub: scrubbing <class 'mutagen.oggopus.OggOpus'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.oggopus.OggOpus'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.oggopus.OggOpus'>
scrub: scrubbing <class 'mutagen.trueaudio.TrueAudio'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.trueaudio.TrueAudio'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.trueaudio.TrueAudio'>
scrub: scrubbing <class 'mutagen.wavpack.WavPack'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.wavpack.WavPack'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.wavpack.WavPack'>
scrub: scrubbing <class 'mutagen.monkeysaudio.MonkeysAudio'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.monkeysaudio.MonkeysAudio'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.monkeysaudio.MonkeysAudio'>
scrub: scrubbing <class 'mutagen.optimfrog.OptimFROG'>
scrub: opening /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac as <class 'mutagen.optimfrog.OptimFROG'>
scrub: failed to open /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac with type <class 'mutagen.optimfrog.OptimFROG'>
scrub: scrubbed tags
scrub: writing new tags after scrub
Sending event: write >>>> GETS STUCK <<<<

So, whatever mutagen is doing is making everything unhappy :/

lovesegfault commented 4 years ago

@sampsyo This may be the root cause: https://github.com/quodlibet/mutagen/issues/389

sampsyo commented 4 years ago

Yes; looks like it could be! Perhaps it's worth trying the workaround from the issue, i.e., from mutagen.flac import delete; delete(..)?

lovesegfault commented 4 years ago

I wanted to, but I'm not sure what should go in the delete() call. I assumed .. wasn't valid, is it?

lovesegfault commented 4 years ago 
plugin paths:
** error loading plugin scrub:
Traceback (most recent call last):
  File "./beets/plugins.py", line 275, in load_plugins
    namespace = __import__(modname, None, None)
  File "./beetsplug/scrub.py", line 109
    delete(..)
           ^
SyntaxError: invalid syntax

Alright, definitely not valid :D

lovesegfault commented 4 years ago

I wonder whether using mediafile instead of mutagen directly could solve the issue.

jackwilsdon commented 4 years ago

I think you pass the mutagen object into delete?

lovesegfault commented 4 years ago

I tried this:

diff --git a/beetsplug/scrub.py b/beetsplug/scrub.py
index a905899d..778317bf 100644
--- a/beetsplug/scrub.py
+++ b/beetsplug/scrub.py
@@ -25,6 +25,7 @@ from beets import util
 from beets import config
 import mediafile
 import mutagen
+from mutagen.flac import delete;

 _MUTAGEN_FORMATS = {
     'asf': 'ASF',
@@ -99,7 +100,7 @@ class ScrubPlugin(BeetsPlugin):

             # Remove the tag for this type.
             try:
-                f.delete()
+                delete(f)
             except NotImplementedError:
                 # Some Mutagen metadata subclasses (namely, ASFTag) do not
                 # support .delete(), presumably because it is impossible to

but it raised

scrub: auto-scrubbing /srv/music/Hubert Laws/Afro-Classic/01.01 Fire and Rain.flac
Traceback (most recent call last):
  File "/nix/store/nq93wrvirbbl1cygn71wwhdbazj6fcv0-python3.8-mutagen-1.44.0/lib/python3.8/site-packages/mutagen/_util.py", line 70, in verify_fileobj
    data = fileobj.read(0)
AttributeError: 'FLAC' object has no attribute 'read'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "./beet", line 23, in <module>
    beets.ui.main()
  File "/home/bemeurer/src/beets/beets/ui/__init__.py", line 1267, in main
    _raw_main(args)
  File "/home/bemeurer/src/beets/beets/ui/__init__.py", line 1254, in _raw_main
    subcommand.func(lib, suboptions, subargs)
  File "/home/bemeurer/src/beets/beets/ui/commands.py", line 956, in import_func
    import_files(lib, paths, query)
  File "/home/bemeurer/src/beets/beets/ui/commands.py", line 926, in import_files
    session.run()
  File "/home/bemeurer/src/beets/beets/importer.py", line 329, in run
    pl.run_parallel(QUEUE_SIZE)
  File "/home/bemeurer/src/beets/beets/util/pipeline.py", line 445, in run_parallel
    six.reraise(exc_info[0], exc_info[1], exc_info[2])
  File "/nix/store/mn2klp7l3kn0lfd8f0scb0yc7svmgjyk-python3.8-six-1.15.0/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/home/bemeurer/src/beets/beets/util/pipeline.py", line 358, in run
    self.coro.send(msg)
  File "/home/bemeurer/src/beets/beets/util/pipeline.py", line 171, in coro
    task = func(*(args + (task,)))
  File "/home/bemeurer/src/beets/beets/importer.py", line 1542, in manipulate_files
    task.manipulate_files(
  File "/home/bemeurer/src/beets/beets/importer.py", line 747, in manipulate_files
    plugins.send('import_task_files', session=session, task=self)
  File "/home/bemeurer/src/beets/beets/plugins.py", line 492, in send
    result = handler(**arguments)
  File "/home/bemeurer/src/beets/beets/plugins.py", line 145, in wrapper
    return func(*args, **kwargs)
  File "/home/bemeurer/src/beets/beetsplug/scrub.py", line 152, in import_task_files
    self._scrub_item(item)
  File "/home/bemeurer/src/beets/beetsplug/scrub.py", line 131, in _scrub_item
    self._scrub(item.path)
  File "/home/bemeurer/src/beets/beetsplug/scrub.py", line 103, in _scrub
    delete(f)
  File "/nix/store/nq93wrvirbbl1cygn71wwhdbazj6fcv0-python3.8-mutagen-1.44.0/lib/python3.8/site-packages/mutagen/_util.py", line 169, in wrapper
    return func(*args, **kwargs)
  File "/nix/store/nq93wrvirbbl1cygn71wwhdbazj6fcv0-python3.8-mutagen-1.44.0/lib/python3.8/site-packages/mutagen/_util.py", line 146, in wrapper_func
    with _openfile(None, filething, filename, fileobj,
  File "/nix/store/f87w21b91cws0wbsvyfn5vnlyv491czi-python3-3.8.3/lib/python3.8/contextlib.py", line 113, in __enter__
    return next(self.gen)
  File "/nix/store/nq93wrvirbbl1cygn71wwhdbazj6fcv0-python3.8-mutagen-1.44.0/lib/python3.8/site-packages/mutagen/_util.py", line 228, in _openfile
    verify_fileobj(fileobj, writable=writable)
  File "/nix/store/nq93wrvirbbl1cygn71wwhdbazj6fcv0-python3.8-mutagen-1.44.0/lib/python3.8/site-packages/mutagen/_util.py", line 73, in verify_fileobj
    raise ValueError("%r not a valid file object" % fileobj)

Seems like it wants a file object, @jackwilsdon?

lovesegfault commented 4 years ago

With this diff:

diff --git a/beetsplug/scrub.py b/beetsplug/scrub.py
index a905899d..d523fc34 100644
--- a/beetsplug/scrub.py
+++ b/beetsplug/scrub.py
@@ -25,6 +25,7 @@ from beets import util
 from beets import config
 import mediafile
 import mutagen
+from mutagen.flac import delete;

 _MUTAGEN_FORMATS = {
     'asf': 'ASF',
@@ -99,7 +100,7 @@ class ScrubPlugin(BeetsPlugin):

             # Remove the tag for this type.
             try:
-                f.delete()
+                delete(util.syspath(path))
             except NotImplementedError:
                 # Some Mutagen metadata subclasses (namely, ASFTag) do not
                 # support .delete(), presumably because it is impossible to

I still get the freeze. I used python's trace mode to see where exactly does it get stuck and it seems to be in the process of resizing the file. I assume it's trying to shrink the file in-place to account for the now-gone metadata?

 --- modulename: flac, funcname: _writeblock
flac.py(124):         data = bytearray()
flac.py(125):         code = (block.code | 128) if is_last else block.code
flac.py(126):         datum = block.write()
 --- modulename: flac, funcname: write
flac.py(653):         try:
flac.py(654):             return b"\x00" * self.length
flac.py(127):         size = len(datum)
flac.py(128):         if size > cls._MAX_SIZE:
flac.py(138):         assert not size > cls._MAX_SIZE
flac.py(139):         length = struct.pack(">I", size)[-3:]
flac.py(140):         data.append(code)
flac.py(141):         data += length
flac.py(142):         data += datum
flac.py(143):         return data
flac.py(168):         return data
flac.py(868):         data_size = len(data)
flac.py(870):         resize_bytes(filething.fileobj, available, data_size, header)
 --- modulename: _util, funcname: resize_bytes
_util.py(909):     if new_size < old_size:
_util.py(910):         delete_size = old_size - new_size
_util.py(911):         delete_at = offset + new_size
_util.py(912):         delete_bytes(fobj, delete_size, delete_at)
 --- modulename: _util, funcname: delete_bytes
_util.py(875):     if size < 0 or offset < 0:
_util.py(878):     fobj.seek(0, 2)
_util.py(879):     filesize = fobj.tell()
_util.py(880):     movesize = filesize - offset - size
_util.py(882):     if movesize < 0:
_util.py(885):     if mmap is not None:
_util.py(886):         try:
_util.py(887):             mmap_move(fobj, offset, offset + size, movesize)
 --- modulename: _util, funcname: mmap_move
_util.py(704):     assert mmap is not None, "no mmap support"
_util.py(706):     if dest < 0 or src < 0 or count < 0:
_util.py(709):     try:
_util.py(710):         fileno = fileobj.fileno()
_util.py(715):     fileobj.seek(0, 2)
_util.py(716):     filesize = fileobj.tell()
_util.py(717):     length = max(dest, src) + count
_util.py(719):     if length > filesize:
_util.py(722):     offset = ((min(dest, src) // mmap.ALLOCATIONGRANULARITY) *
_util.py(723):               mmap.ALLOCATIONGRANULARITY)
_util.py(722):     offset = ((min(dest, src) // mmap.ALLOCATIONGRANULARITY) *
_util.py(724):     assert dest >= offset
_util.py(725):     assert src >= offset
_util.py(726):     assert offset % mmap.ALLOCATIONGRANULARITY == 0
_util.py(729):     if count == 0:
_util.py(733):     if src == dest:
_util.py(736):     fileobj.flush()
_util.py(737):     file_map = mmap.mmap(fileno, length - offset, offset=offset)
_util.py(738):     try:
_util.py(739):         file_map.move(dest - offset, src - offset, count)
lovesegfault commented 4 years ago

Alright, on the OpenZFS IRC someone mentioned the issue seems to be the mmap based file writing mutagen seems to be doing (see trace above). ZFS isn't integrated with the linux cache, and so each mmap operation needs to be copied in and out of the cache making it painfully slow.

While mutagen does not allow you to toggle mmap on and off, it does have fallback methods and so if you simply patch mmap = None it will use those and everything will work as expected:

diff --git a/mutagen/_util.py b/mutagen/_util.py
index 1332f9d..5b9a8cd 100644
--- a/mutagen/_util.py
+++ b/mutagen/_util.py
@@ -20,7 +20,7 @@ import decimal
 from io import BytesIO

 try:
-    import mmap
+    mmap = None
 except ImportError:
     # Google App Engine has no mmap:
     #   https://github.com/quodlibet/mutagen/issues/286
@@ -701,8 +701,6 @@ def mmap_move(fileobj, dest, src, count):
         ValueError: In case invalid parameters were given
     """

-    assert mmap is not None, "no mmap support"
-
     if dest < 0 or src < 0 or count < 0:
         raise ValueError("Invalid parameters")

diff --git a/tests/test__util.py b/tests/test__util.py
index 0ed25ed..55d0d7a 100644
--- a/tests/test__util.py
+++ b/tests/test__util.py
@@ -2,7 +2,7 @@

 from mutagen._util import DictMixin, cdata, insert_bytes, delete_bytes, \
     decode_terminated, dict_match, enum, get_size, BitReader, BitReaderError, \
-    resize_bytes, seek_end, mmap_move, verify_fileobj, fileobj_name, \
+    resize_bytes, seek_end, verify_fileobj, fileobj_name, \
     read_full, flags, resize_file, fallback_move, encode_endian, loadfile, \
     intround, verify_filename
 from mutagen._compat import text_type, itervalues, iterkeys, iteritems, PY2, \
@@ -376,33 +376,12 @@ class TMoveMixin(object):
             self.MOVE(o, 0, 1, 2)
             self.MOVE(o, 1, 0, 2)

-    def test_larger_than_page_size(self):
-        off = mmap.ALLOCATIONGRANULARITY
-        with self.file(b"f" * off * 2) as o:
-            self.MOVE(o, off, off + 1, off - 1)
-            self.MOVE(o, off + 1, off, off - 1)
-
-        with self.file(b"f" * off * 2 + b"x") as o:
-            self.MOVE(o, off * 2 - 1, off * 2, 1)
-            self.assertEqual(self.read(o)[-3:], b"fxx")
-

 class Tfallback_move(TestCase, TMoveMixin):

     MOVE = staticmethod(fallback_move)

-class MmapMove(TestCase, TMoveMixin):
-
-    MOVE = staticmethod(mmap_move)
-
-    def test_stringio(self):
-        self.assertRaises(mmap.error, mmap_move, cBytesIO(), 0, 0, 0)
-
-    def test_no_fileno(self):
-        self.assertRaises(mmap.error, mmap_move, object(), 0, 0, 0)
-
-
 class FileHandling(TestCase):
     def file(self, contents):
         temp = tempfile.TemporaryFile()

So, to sum up the issue:

  1. It's not beets' fault, but mutagen's
  2. mmap file writing is unusable in ZFS
  3. This can be mitigated by applying the above patch to mutagen

I will open an issue in the mutagen tracker and cross-link here. Thanks @sampsyo for all the direction while debugging!

sampsyo commented 4 years ago

Awesome! Glad I could be (even slightly) helpful. :smiley:

nektro commented 1 year ago

I experience this issue on https://github.com/beetbox/beets/commit/e06cf7969bfdfa4773049699320471be45d56054 (NixOS 22.05 using beets-unstable)

Python version 3.9.15
plugins: absubmit, chroma, fromfilename

edit: trying to run beet import -m . and its hanging with no output

edit: adding -vvvv i can see its trying to chromaprint every file before even bringing up the first prompt

edit: made it to the end where its importing now and seems to be running chroma all over again for each track, not sure what the first loop was for then