kagemomiji / airsonic-advanced

airsonic-advanced
GNU General Public License v3.0
152 stars 14 forks source link

[Bug]: Transcoder latency when the external client seeks #209

Closed yatli closed 1 year ago

yatli commented 1 year ago

What happened?

This one does not affect normal playback experience, but makes client-side seeking slow, since every time it needs to wait for the server to finish transcoding.

Steps to reproduce

  1. Play a song with external client. watch server cpu activity and wait for transcoder to finish.
  2. Seek forward or backward significantly, like 3mins or longer
  3. Do it a few times

Expect: the transcoder can start from an offset within the track, "near" the seek destination, so that playback resumes quickly after seek Actual: transcoder takes a long time to finish, blocking playback.

Version

11.1.1 (Stable)

Version Detail

11.1.1 release

Operating System

ArchLinux w/Docker

Java Version

Docker default

Database

Other

DB Detail

Docker default

Configuration paramter

The disc is FLAC encodec and track-split, no CUE involved. Transcoder command: ffmpeg %S -i %s -map 0:0 -b:a %bk -v 0 -f mp3 -

Proxy Server

No response

client detail

No response

language

None

Relevant log output

[Playback starts]

airsonic-airsonic-advanced-1  | 2023-04-30 11:11:53.160  INFO --- o.a.p.c.StreamController                 : 192.168.50.1: yatli listening to 4. Adrastea/SUPER MOON - instrumental.flac in folder 2
airsonic-airsonic-advanced-1  | 2023-04-30 11:11:53.161  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 59472 | EventType: REMOVED | Old value: SUPER MOON - instrumental | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:11:53.161  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 59409 | EventType: REMOVED | Old value: 4. Adrastea | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:11:53.161  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: REMOVED | Old value: 4. Adrastea | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:11:53.162  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-i][/var/touhou/[ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea/SUPER MOON - instrumental.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]

[Seek]

airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.740  INFO --- o.a.p.s.LoggingExceptionResolver         : 192.168.50.1: Client unexpectedly closed connection while loading https://music.yatao.info:10443/rest/stream.view?id=59472&v=1.13.0&c=sonixd&p=<hidden>&u=<hidden> (java.io.IOException: Broken pipe)
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.740  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: REMOVED | Old value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"] | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.740  INFO --- o.a.player.filter.RESTFilter             : 192.168.50.1: Client unexpectedly closed connection while loading https://music.yatao.info:10443/rest/stream.view?id=59472&v=1.13.0&c=sonixd&p=<hidden>&u=<hidden> (java.io.IOException: Broken pipe)
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.825  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 59472 | EventType: CREATED | Old value: null | New value: SUPER MOON - instrumental
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.825  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 59472 | EventType: REMOVED | Old value: SUPER MOON - instrumental | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.825  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: CREATED | Old value: null | New value: 4. Adrastea
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.826  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: REMOVED | Old value: 4. Adrastea | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.845  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: CREATED | Old value: null | New value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"]
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.846  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 59472 | EventType: CREATED | Old value: null | New value: SUPER MOON - instrumental
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.847  INFO --- o.a.p.c.StreamController                 : 192.168.50.1: yatli listening to 4. Adrastea/SUPER MOON - instrumental.flac in folder 2
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.847  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: 59472 | EventType: REMOVED | Old value: SUPER MOON - instrumental | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.848  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: CREATED | Old value: null | New value: 4. Adrastea
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.848  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: REMOVED | Old value: 4. Adrastea | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:01.849  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-i][/var/touhou/[ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea/SUPER MOON - instrumental.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:14.073  INFO --- o.a.p.c.StreamController                 : 192.168.50.1: yatli listening to 4. Adrastea/SUPER MOON - instrumental.flac in folder 2
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:14.074  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: CREATED | Old value: null | New value: 4. Adrastea
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:14.075  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: [ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea-2--1.0 | EventType: REMOVED | Old value: 4. Adrastea | New value: null
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:14.076  INFO --- o.a.p.io.TranscodeInputStream            : Starting transcoder: [/var/airsonic/transcode/ffmpeg][-i][/var/touhou/[ShibayanRecords]/2019.09.20 [STAL-1902] ShibayanRecords Instrumental Vol.3/flac/4. Adrastea/SUPER MOON - instrumental.flac][-map][0:0][-b:a][192k][-v][0][-f][mp3][-]
airsonic-airsonic-advanced-1  | 2023-04-30 11:12:14.081  INFO --- o.a.p.s.CacheConfiguration$CacheLogger   : Cache Key: yatli | EventType: REMOVED | Old value: yatli ["STREAM","COVERART","UPLOAD","SETTINGS","DOWNLOAD","JUKEBOX","ADMIN","COMMENT","PODCAST","SHARE"] | New value: null
kagemomiji commented 1 year ago

@yatli Could you give me details about your external client? Are you using Sublime (Linux) and D-sub/Subsonic (Android) as you mentioned in #195?

yatli commented 1 year ago

I'm using Sonixd on Windows this time.

Notable settings:

  1. Gapless preset activated
  2. Song cache is OFF

Full config, minus the theme settings:

{
    "discord": {
        "enabled": false,
        "clientId": "923372440934055968",
        "serverImage": false
    },
    "obs": {
        "enabled": false,
        "url": "",
        "type": "local",
        "path": "",
        "pollingInterval": 2000
    },
    "transcode": false,
    "resume": false,
    "autoUpdate": true,
    "autoUpdateNotice": false,
    "serverType": "subsonic",
    "legacyAuth": true,
    "language": "en",
    "theme": "defaultDark",
    "font": "Poppins",
    "dynamicBackground": false,
    "highlightOnRowHover": true,
    "minimizeToTray": true,
    "showDebugWindow": false,
    "globalMediaHotkeys": false,
    "systemMediaTransportControls": true,
    "artistPageLegacy": false,
    "startPage": "/",
    "scrobble": true,
    "systemNotifications": false,
    "musicFolder": {
        "id": null,
        "albums": true,
        "artists": true,
        "dashboard": false,
        "search": false,
        "starred": false,
        "music": true
    },
    "sidebar": {
        "expand": true,
        "width": "225px",
        "coverArt": true,
        "selected": [
            "dashboard",
            "nowplaying",
            "favorites",
            "songs",
            "albums",
            "artists",
            "genres",
            "folders",
            "config",
            "collapse",
            "playlists",
            "playlistList"
        ]
    },
    "selected": [
        "dashboard",
        "nowplaying",
        "favorites",
        "songs",
        "albums",
        "artists",
        "genres",
        "folders",
        "config",
        "collapse",
        "playlists",
        "playlistList"
    ],
    "pagination": {
        "music": {
            "recordsPerPage": 50,
            "serverSide": true
        },
        "album": {
            "recordsPerPage": 50,
            "serverSide": false
        }
    },
    "volume": 1,
    "audioDeviceId": null,
    "seekForwardInterval": 5,
    "seekBackwardInterval": 5,
    "volumeFade": true,
    "repeat": "none",
    "shuffle": false,
    "scrollWithCurrentSong": true,
    "cacheImages": true,
    "cacheSongs": false,
    "pollingInterval": 15,
    "fadeDuration": 0,
    "fadeType": "equalPower",
    "gridCardSize": 175,
    "gridGapSize": 20,
    "gridAlignment": "flex-start",
    "playlistViewType": "list",
    "albumViewType": "list",
    "albumSortDefault": "random",
    "musicSortDefault": "random",
    "artistViewType": "list",
    "musicListFontSize": "14",
    "musicListRowHeight": "60.0",
    "randomPlaylistTrackCount": 50,
    "playbackFilters": [
        {
            "filter": "(\\(|\\[|~|-|()[Oo]ff [Vv]ocal(\\)|\\]|~|-|))",
            "enabled": false
        },
        {
            "filter": "((|\\(|\\[|~|-)[Ii]nst(rumental)?(\\)|\\]|~|-|))",
            "enabled": false
        }
    ],
    "exitToTray": false,
    "cachePath": "C:\\Users\\Yatao\\AppData\\Roaming\\Sonixd",
    "titleBarStyle": "windows",
    "server": "XXX",
    "serverBase64": "XXX",
    "username": "XXX",
    "password": "XXX",
    "salt": "XXX",
    "hash": "XXX"
}
yatli commented 1 year ago

I can also test other clients. Will update this post when it's done.

yatli commented 1 year ago

@kagemomiji I tested a few aspects.

  1. DSub default settings. Seek incurs no latency; No transcoder activity on server.
  2. DSub, set cache size to 0MB (does it really turn the cache off this way?), clear cache. Seek incurs no latency; No transcoder activity on server.
  3. Sonixd win11, default settings. Song cache is disabled. Seek incurs latency; Transcoder activated on seek.
  4. Sonixd win11, Song cache is enabled. Since Sonixd only caches a song when it finishes without changing track, I let it do so. After the track is cached, seek incurs latency; Transcoder activated on seek.

image

... It wants the server to serve even if it has a cached song 😅

So I'm learning my lesson here, clients have different quirks.

kagemomiji commented 1 year ago

@yatli Thank you for your experiments.

I think that the reported bug is related to the client-side rather than the server-side(airsonic-advanced).

To minimize the seek latency, caching in client is a good solution, as demonstrated by the DSub experiment. If Sonixd properly manages the cache, there should be no need to transcode audio in airsonic-advanced.

Fortunately, ffmpeg supports seeking before encoding, so I can implement the /stream API to utilize this functionality. (There is offset query parameter, but for video https://opensubsonic.netlify.app/docs/endpoints/stream/) However, this cannot be achieved solely with a server-side implementation. Client-side implementation is also necessary since the server-side needs to know where in the audio to start, but Subsonic clients do not currently support such a request.

yatli commented 1 year ago

Thanks for explaining this.

Expect: the transcoder can start from an offset within the track, "near" the seek destination, so that playback resumes quickly after seek

I took it for granted that airsonic already has this feature, but it turns out to be the over-engineered imagination in my head :)