diff --git a/web_server.py b/web_server.py index 1b0f9aa6..b1059a93 100644 --- a/web_server.py +++ b/web_server.py @@ -2533,7 +2533,9 @@ def _run_sync_task(playlist_id, playlist_name, tracks_json): """The actual sync function that runs in the background thread.""" global sync_states, sync_service - print(f"๐Ÿš€ _run_sync_task STARTED for playlist '{playlist_name}' (ID: {playlist_id})") + import time + task_start_time = time.time() + print(f"๐Ÿš€ [TIMING] _run_sync_task STARTED for playlist '{playlist_name}' at {time.strftime('%H:%M:%S')}") print(f"๐Ÿ“Š Received {len(tracks_json)} tracks from frontend") try: @@ -2571,8 +2573,15 @@ def _run_sync_task(playlist_id, playlist_name, tracks_json): ) print(f"โœ… Created SpotifyPlaylist object: '{playlist.name}' with {playlist.total_tracks} tracks") + first_callback_time = [None] # Use list to allow modification in nested function + def progress_callback(progress): """Callback to update the shared state.""" + if first_callback_time[0] is None: + first_callback_time[0] = time.time() + first_callback_duration = (first_callback_time[0] - task_start_time) * 1000 + print(f"โฑ๏ธ [TIMING] FIRST progress callback at {time.strftime('%H:%M:%S')} (took {first_callback_duration:.1f}ms from start)") + print(f"โšก PROGRESS CALLBACK: {progress.current_step} - {progress.current_track}") print(f" ๐Ÿ“Š Progress: {progress.progress}% ({progress.matched_tracks}/{progress.total_tracks} matched, {progress.failed_tracks} failed)") @@ -2684,9 +2693,17 @@ def _run_sync_task(playlist_id, playlist_name, tracks_json): sync_service._find_track_in_media_server = database_only_find_track print(f"โœ… Patched sync service to use database-only matching") + sync_start_time = time.time() + setup_duration = (sync_start_time - task_start_time) * 1000 + print(f"โฑ๏ธ [TIMING] Setup completed at {time.strftime('%H:%M:%S')} (took {setup_duration:.1f}ms)") print(f"๐Ÿš€ Starting actual sync process with asyncio.run()...") + # Run the sync (this is a blocking call within this thread) result = asyncio.run(sync_service.sync_playlist(playlist, download_missing=False)) + + sync_duration = (time.time() - sync_start_time) * 1000 + total_duration = (time.time() - task_start_time) * 1000 + print(f"โฑ๏ธ [TIMING] Sync completed at {time.strftime('%H:%M:%S')} (sync: {sync_duration:.1f}ms, total: {total_duration:.1f}ms)") print(f"โœ… Sync process completed! Result type: {type(result)}") print(f" Result details: matched={getattr(result, 'matched_tracks', 'N/A')}, total={getattr(result, 'total_tracks', 'N/A')}") @@ -2723,6 +2740,10 @@ def _run_sync_task(playlist_id, playlist_name, tracks_json): @app.route('/api/sync/start', methods=['POST']) def start_playlist_sync(): """Starts a new sync process for a given playlist.""" + import time + request_start_time = time.time() + print(f"โฑ๏ธ [TIMING] Sync request received at {time.strftime('%H:%M:%S')}") + data = request.get_json() playlist_id = data.get('playlist_id') playlist_name = data.get('playlist_name') @@ -2730,6 +2751,8 @@ def start_playlist_sync(): if not all([playlist_id, playlist_name, tracks_json]): return jsonify({"success": False, "error": "Missing playlist_id, name, or tracks."}), 400 + + print(f"โฑ๏ธ [TIMING] Request parsed at {time.strftime('%H:%M:%S')} (took {(time.time()-request_start_time)*1000:.1f}ms)") with sync_lock: if playlist_id in active_sync_workers and not active_sync_workers[playlist_id].done(): @@ -2739,9 +2762,14 @@ def start_playlist_sync(): sync_states[playlist_id] = {"status": "starting", "progress": {}} # Submit the task to the thread pool + thread_submit_time = time.time() future = sync_executor.submit(_run_sync_task, playlist_id, playlist_name, tracks_json) active_sync_workers[playlist_id] = future + thread_submit_duration = (time.time() - thread_submit_time) * 1000 + print(f"โฑ๏ธ [TIMING] Thread submitted at {time.strftime('%H:%M:%S')} (took {thread_submit_duration:.1f}ms)") + total_request_time = (time.time() - request_start_time) * 1000 + print(f"โฑ๏ธ [TIMING] Request completed at {time.strftime('%H:%M:%S')} (total: {total_request_time:.1f}ms)") return jsonify({"success": True, "message": "Sync started."}) diff --git a/webui/static/script.js b/webui/static/script.js index d2eba2d7..8f430086 100644 --- a/webui/static/script.js +++ b/webui/static/script.js @@ -1616,7 +1616,8 @@ function formatDuration(ms) { // Find and REPLACE the old startPlaylistSyncFromModal function async function startPlaylistSync(playlistId) { - console.log(`๐Ÿš€ Starting sync for playlist: ${playlistId}`); + const startTime = Date.now(); + console.log(`๐Ÿš€ [${new Date().toTimeString().split(' ')[0]}] Starting sync for playlist: ${playlistId}`); const playlist = spotifyPlaylists.find(p => p.id === playlistId); if (!playlist) { console.error(`โŒ Could not find playlist data for ID: ${playlistId}`); @@ -1628,37 +1629,30 @@ async function startPlaylistSync(playlistId) { // Ensure we have the full track list before starting let tracks = playlistTrackCache[playlistId]; if (!tracks) { - console.log(`๐Ÿ”„ Cache miss - fetching tracks for playlist ${playlistId}`); + const trackFetchStart = Date.now(); + console.log(`๐Ÿ”„ [${new Date().toTimeString().split(' ')[0]}] Cache miss - fetching tracks for playlist ${playlistId}`); try { const response = await fetch(`/api/spotify/playlist/${playlistId}`); const fullPlaylist = await response.json(); if (fullPlaylist.error) throw new Error(fullPlaylist.error); tracks = fullPlaylist.tracks; playlistTrackCache[playlistId] = tracks; // Cache it - console.log(`โœ… Fetched and cached ${tracks.length} tracks`); + const trackFetchTime = Date.now() - trackFetchStart; + console.log(`โœ… [${new Date().toTimeString().split(' ')[0]}] Fetched and cached ${tracks.length} tracks (took ${trackFetchTime}ms)`); } catch (error) { console.error(`โŒ Failed to fetch tracks:`, error); showToast(`Failed to fetch tracks for sync: ${error.message}`, 'error'); return; } } else { - console.log(`โœ… Using cached tracks: ${tracks.length} tracks`); + console.log(`โœ… [${new Date().toTimeString().split(' ')[0]}] Using cached tracks: ${tracks.length} tracks`); } // DON'T close the modal - let it show live progress like the GUI try { - // First test database access - console.log(`๐Ÿงช Testing database access before sync...`); - try { - const testResponse = await fetch('/api/sync/test-database'); - const testData = await testResponse.json(); - console.log(`๐Ÿงช Database test result:`, testData); - } catch (testError) { - console.warn(`โš ๏ธ Database test failed:`, testError); - } - - console.log(`๐Ÿ”„ Making API call to /api/sync/start with ${tracks.length} tracks`); + const syncStartTime = Date.now(); + console.log(`๐Ÿ”„ [${new Date().toTimeString().split(' ')[0]}] Making API call to /api/sync/start with ${tracks.length} tracks`); const response = await fetch('/api/sync/start', { method: 'POST', headers: { 'Content-Type': 'application/json' }, @@ -1669,13 +1663,15 @@ async function startPlaylistSync(playlistId) { }) }); - console.log(`๐Ÿ“ก API response status: ${response.status}`); + const syncRequestTime = Date.now() - syncStartTime; + console.log(`๐Ÿ“ก [${new Date().toTimeString().split(' ')[0]}] API response status: ${response.status} (took ${syncRequestTime}ms)`); const data = await response.json(); - console.log(`๐Ÿ“ก API response data:`, data); + console.log(`๐Ÿ“ก [${new Date().toTimeString().split(' ')[0]}] API response data:`, data); if (!data.success) throw new Error(data.error); - console.log(`โœ… Sync started successfully for "${playlist.name}"`); + const totalTime = Date.now() - startTime; + console.log(`โœ… [${new Date().toTimeString().split(' ')[0]}] Sync started successfully for "${playlist.name}" (total time: ${totalTime}ms)`); showToast(`Sync started for "${playlist.name}"`, 'success'); // Show initial sync state in modal if open @@ -1684,7 +1680,7 @@ async function startPlaylistSync(playlistId) { const statusDisplay = document.getElementById(`modal-sync-status-${playlist.id}`); if (statusDisplay) { statusDisplay.style.display = 'flex'; - console.log(`๐Ÿ“Š Showing modal sync status for ${playlist.id}`); + console.log(`๐Ÿ“Š [${new Date().toTimeString().split(' ')[0]}] Showing modal sync status for ${playlist.id}`); } }