perf(call): Debug starting a big call takes long

lib/Activity/Listener.php

@@ -74,6 +74,9 @@ public function handle(Event $event): void {
 	}
 
 	protected function setActive(ParticipantModifiedEvent $event): void {
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #2.0: ' . microtime(true));
+		}
 		if ($event->getProperty() !== AParticipantModifiedEvent::PROPERTY_IN_CALL) {
 			return;
 		}
@@ -82,14 +85,16 @@ protected function setActive(ParticipantModifiedEvent $event): void {
 			|| $event->getNewValue() === Participant::FLAG_DISCONNECTED) {
 			return;
 		}
-
 		$participant = $event->getParticipant();
 		$this->roomService->setActiveSince(
 			$event->getRoom(),
 			$this->timeFactory->getDateTime(),
 			$participant->getSession() ? $participant->getSession()->getInCall() : Participant::FLAG_DISCONNECTED,
 			$participant->getAttendee()->getActorType() !== Attendee::ACTOR_USERS
 		);
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #2.1: ' . microtime(true));
+		}
 	}
 
 	protected function handleParticipantModified(ParticipantModifiedEvent $event): void {

lib/Controller/CallController.php

@@ -141,6 +141,9 @@ public function getPeersForCall(): DataResponse {
 	#[RequireParticipant]
 	#[RequireReadWriteConversation]
 	public function joinCall(?int $flags = null, ?int $forcePermissions = null, bool $silent = false, bool $recordingConsent = false): DataResponse {
+		if ($this->room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #0.0: ' . microtime(true));
+		}
 		if (!$recordingConsent && $this->talkConfig->recordingConsentRequired() !== RecordingService::CONSENT_REQUIRED_NO) {
 			if ($this->talkConfig->recordingConsentRequired() === RecordingService::CONSENT_REQUIRED_YES) {
 				return new DataResponse(['error' => 'consent'], Http::STATUS_BAD_REQUEST);
@@ -169,9 +172,13 @@ public function joinCall(?int $flags = null, ?int $forcePermissions = null, bool
 		if ($forcePermissions !== null && $this->participant->hasModeratorPermissions()) {
 			$this->roomService->setPermissions($this->room, 'call', Attendee::PERMISSIONS_MODIFY_SET, $forcePermissions, true);
 		}
-
+		if ($this->room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #0.1: ' . microtime(true));
+		}
 		$joined = $this->participantService->changeInCall($this->room, $this->participant, $flags, false, $silent);
-
+		if ($this->room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #0.2: ' . microtime(true));
+		}
 		if (!$joined) {
 			return new DataResponse([], Http::STATUS_BAD_REQUEST);
 		}

lib/Listener/RestrictStartingCalls.php

@@ -53,6 +53,9 @@ public function handle(Event $event): void {
 		if (!$event instanceof BeforeParticipantModifiedEvent) {
 			return;
 		}
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #3.0: ' . microtime(true));
+		}
 
 		if ($event->getProperty() !== AParticipantModifiedEvent::PROPERTY_IN_CALL) {
 			return;
@@ -74,5 +77,8 @@ public function handle(Event $event): void {
 			&& !$this->participantService->hasActiveSessionsInCall($room)) {
 			throw new ForbiddenException('Can not start a call');
 		}
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #3.1: ' . microtime(true));
+		}
 	}
 }

lib/Notification/Listener.php

@@ -41,10 +41,12 @@
 use OCP\EventDispatcher\Event;
 use OCP\EventDispatcher\IEventDispatcher;
 use OCP\EventDispatcher\IEventListener;
+use OCP\IConfig;
 use OCP\IDBConnection;
 use OCP\IUser;
 use OCP\IUserSession;
 use OCP\Notification\IManager;
+use OCP\Notification\INotification;
 use Psr\Log\LoggerInterface;
 
 /**
@@ -53,10 +55,14 @@
 class Listener implements IEventListener {
 
 	protected bool $shouldSendCallNotification = false;
+	/** @var array<string, INotification> $preparedCallNotifications Map of language => parsed notification in that language */
+	protected array $preparedCallNotifications = [];
 
 	public function __construct(
+		protected IConfig $serverConfig,
 		protected IDBConnection $connection,
 		protected IManager $notificationManager,
+		protected Notifier $notificationProvider,
 		protected ParticipantService $participantsService,
 		protected IEventDispatcher $dispatcher,
 		protected IUserSession $userSession,
@@ -227,10 +233,19 @@ protected function afterParticipantJoinedCall(ParticipantModifiedEvent $event):
 			return;
 		}
 
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #4.0: ' . microtime(true));
+		}
 		$this->markCallNotificationsRead($event->getRoom());
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #4.1: ' . microtime(true));
+		}
 		if ($this->shouldSendCallNotification) {
 			$this->sendCallNotifications($event->getRoom());
 		}
+		if ($event->getRoom()->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #4.2: ' . microtime(true));
+		}
 	}
 
 	/**
@@ -263,6 +278,9 @@ protected function markCallNotificationsRead(Room $room): void {
 	 * @param Room $room
 	 */
 	protected function sendCallNotifications(Room $room): void {
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #7.0: ' . microtime(true));
+		}
 		$actor = $this->userSession->getUser();
 		$actorId = $actor instanceof IUser ? $actor->getUID() :'';
 
@@ -290,30 +308,86 @@ protected function sendCallNotifications(Room $room): void {
 			return;
 		}
 
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #7.1: ' . microtime(true));
+		}
+		$this->preparedCallNotifications = [];
 		$userIds = $this->participantsService->getParticipantUserIdsForCallNotifications($room);
+		// Room name depends on the notification user for one-to-one,
+		// so we avoid preparsing it there. Also, it comes with some base load,
+		// so we only do it for "big enough" calls.
+		$preparseNotificationForPush = count($userIds) > 10;
+		if ($preparseNotificationForPush) {
+			$fallbackLang = $this->serverConfig->getSystemValue('force_language', null);
+			if (is_string($fallbackLang)) {
+				/** @psalm-var array<string, string> $userLanguages */
+				$userLanguages = [];
+			} else {
+				$fallbackLang = $this->serverConfig->getSystemValueString('default_language', 'en');
+				/** @psalm-var array<string, string> $userLanguages */
+				$userLanguages = $this->serverConfig->getUserValueForUsers('core', 'lang', $userIds);
+			}
+		}
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #7.2: ' . microtime(true));
+		}
+
 		$this->connection->beginTransaction();
 		try {
 			foreach ($userIds as $userId) {
 				if ($actorId === $userId) {
 					continue;
 				}
 
+				if ($preparseNotificationForPush) {
+					// Get the settings for this particular user, then check if we have notifications to email them
+					$languageCode = $userLanguages[$userId] ?? $fallbackLang;
+
+					if (!isset($this->preparedCallNotifications[$languageCode])) {
+						$translatedNotification = clone $notification;
+
+						$this->notificationManager->setPreparingPushNotification(true);
+						$this->preparedCallNotifications[$languageCode] = $this->notificationProvider->prepare($translatedNotification, $languageCode);
+						$this->notificationManager->setPreparingPushNotification(false);
+						$userNotification = $translatedNotification;
+						if ($room->getToken() === 'c9bui2ju') {
+							\OC::$server->getLogger()->warning('Debugging step #7.2.' . $languageCode . ': ' . microtime(true));
+						}
+					} else {
+						$userNotification = $this->preparedCallNotifications[$languageCode];
+						if ($room->getToken() === 'c9bui2ju') {
+							\OC::$server->getLogger()->warning('Debugging step #7.2.reused.' . $languageCode . ': ' . microtime(true));
+						}
+					}
+				} else {
+					$userNotification = $notification;
+				}
+
 				try {
-					$notification->setUser($userId);
-					$this->notificationManager->notify($notification);
+					$userNotification->setUser($userId);
+					$this->notificationManager->notify($userNotification);
 				} catch (\InvalidArgumentException $e) {
 					$this->logger->error($e->getMessage(), ['exception' => $e]);
 				}
+				if ($room->getToken() === 'c9bui2ju') {
+					\OC::$server->getLogger()->warning('Debugging step #7.2.' . $userId . ': ' . microtime(true));
+				}
 			}
 		} catch (\Throwable $e) {
 			$this->connection->rollBack();
 			throw $e;
 		}
 		$this->connection->commit();
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #7.3: ' . microtime(true));
+		}
 
 		if ($shouldFlush) {
 			$this->notificationManager->flush();
 		}
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #7.4: ' . microtime(true));
+		}
 	}
 
 	/**

lib/Notification/Notifier.php

@@ -197,10 +197,12 @@ public function prepare(INotification $notification, string $languageCode): INot
 			throw new \InvalidArgumentException('Incorrect app');
 		}
 
-		$userId = $notification->getUser();
-		$user = $this->userManager->get($userId);
-		if (!$user instanceof IUser || $this->config->isDisabledForUser($user)) {
-			throw new AlreadyProcessedException();
+		if (!($this->notificationManager->isPreparingPushNotification() && $notification->getSubject() === 'call')) {
+			$userId = $notification->getUser();
+			$user = $this->userManager->get($userId);
+			if (!$user instanceof IUser || $this->config->isDisabledForUser($user)) {
+				throw new AlreadyProcessedException();
+			}
 		}
 
 		$l = $this->lFactory->get(Application::APP_ID, $languageCode);
@@ -217,20 +219,27 @@ public function prepare(INotification $notification, string $languageCode): INot
 			return $this->parseCertificateExpiration($notification, $l);
 		}
 
-		try {
-			$room = $this->getRoom($notification->getObjectId(), $userId);
-		} catch (RoomNotFoundException $e) {
-			// Room does not exist
-			throw new AlreadyProcessedException();
-		}
-
 		if ($this->notificationManager->isPreparingPushNotification() && $notification->getSubject() === 'call') {
+			try {
+				$room = $this->manager->getRoomByToken($notification->getObjectId());
+			} catch (RoomNotFoundException) {
+				// Room does not exist
+				throw new AlreadyProcessedException();
+			}
+
 			// Skip the participant check when we generate push notifications
 			// we just looped over the participants to create the notification,
 			// they can not be removed between these 2 steps, but we can save
 			// n queries.
 			$participant = null;
 		} else {
+			try {
+				$room = $this->getRoom($notification->getObjectId(), $userId);
+			} catch (RoomNotFoundException $e) {
+				// Room does not exist
+				throw new AlreadyProcessedException();
+			}
+
 			try {
 				$participant = $this->getParticipant($room, $userId);
 			} catch (ParticipantNotFoundException $e) {

lib/Service/ParticipantService.php

@@ -1131,6 +1131,9 @@ public function endCallForEveryone(Room $room, Participant $moderator): void {
 	}
 
 	public function changeInCall(Room $room, Participant $participant, int $flags, bool $endCallForEveryone = false, bool $silent = false): bool {
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #1.0: ' . microtime(true));
+		}
 		if ($room->getType() === Room::TYPE_CHANGELOG
 			|| $room->getType() === Room::TYPE_ONE_TO_ONE_FORMER
 			|| $room->getType() === Room::TYPE_NOTE_TO_SELF) {
@@ -1153,6 +1156,10 @@ public function changeInCall(Room $room, Participant $participant, int $flags, b
 		$oldFlags = $session->getInCall();
 		$details = [];
 
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #1.1: ' . microtime(true));
+		}
+
 		if ($flags !== Participant::FLAG_DISCONNECTED && $silent) {
 			$details = [AParticipantModifiedEvent::DETAIL_IN_CALL_SILENT => $silent];
 		} elseif ($flags === Participant::FLAG_DISCONNECTED && $endCallForEveryone) {
@@ -1161,7 +1168,9 @@ public function changeInCall(Room $room, Participant $participant, int $flags, b
 
 		$event = new BeforeParticipantModifiedEvent($room, $participant, AParticipantModifiedEvent::PROPERTY_IN_CALL, $flags, $oldFlags, $details);
 		$this->dispatcher->dispatchTyped($event);
-
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #1.2: ' . microtime(true));
+		}
 		$session->setInCall($flags);
 		if (!$endCallForEveryone) {
 			$this->sessionMapper->update($session);
@@ -1176,8 +1185,14 @@ public function changeInCall(Room $room, Participant $participant, int $flags, b
 			$this->attendeeMapper->update($attendee);
 		}
 
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #1.3: ' . microtime(true));
+		}
 		$event = new ParticipantModifiedEvent($room, $participant, AParticipantModifiedEvent::PROPERTY_IN_CALL, $flags, $oldFlags, $details);
 		$this->dispatcher->dispatchTyped($event);
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #1.4: ' . microtime(true));
+		}
 
 		return true;
 	}

lib/Signaling/BackendNotifier.php

@@ -132,11 +132,17 @@ private function backendRequest(Room $room, array $data): ?IResponse {
 			'Content-Type' => 'application/json',
 		];
 
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #6.0: ' . microtime(true));
+		}
 		$random = $this->secureRandom->generate(64);
 		$hash = hash_hmac('sha256', $random . $body, $this->config->getSignalingSecret());
 		$headers['Spreed-Signaling-Random'] = $random;
 		$headers['Spreed-Signaling-Checksum'] = $hash;
 		$headers['Spreed-Signaling-Backend'] = $this->urlGenerator->getAbsoluteURL('');
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #6.1: ' . microtime(true));
+		}
 
 		$params = [
 			'headers' => $headers,
@@ -411,15 +417,24 @@ public function participantsModified(Room $room, array $sessionIds): void {
 	 */
 	public function roomInCallChanged(Room $room, int $flags, array $sessionIds, bool $changeAll = false): void {
 		if ($changeAll) {
+			if ($room->getToken() === 'c9bui2ju') {
+				\OC::$server->getLogger()->warning('Debugging step #5.a: ' . microtime(true));
+			}
 			$data = [
 				'incall' => $flags,
 				'all' => true
 			];
 		} else {
+			if ($room->getToken() === 'c9bui2ju') {
+				\OC::$server->getLogger()->warning('Debugging step #5.b: ' . microtime(true));
+			}
 			$changed = [];
 			$users = [];
 
 			$participants = $this->participantService->getParticipantsForAllSessions($room);
+			if ($room->getToken() === 'c9bui2ju') {
+				\OC::$server->getLogger()->warning('Debugging step #5.1: ' . microtime(true));
+			}
 			foreach ($participants as $participant) {
 				$session = $participant->getSession();
 				if (!$session instanceof Session) {
@@ -460,6 +475,10 @@ public function roomInCallChanged(Room $room, int $flags, array $sessionIds, boo
 			];
 		}
 
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #5.2: ' . microtime(true));
+		}
+
 		$start = microtime(true);
 		$this->backendRequest($room, [
 			'type' => 'incall',
@@ -473,6 +492,9 @@ public function roomInCallChanged(Room $room, int $flags, array $sessionIds, boo
 			'duration' => sprintf('%.2f', $duration),
 			'app' => 'spreed-hpb',
 		]);
+		if ($room->getToken() === 'c9bui2ju') {
+			\OC::$server->getLogger()->warning('Debugging step #5.3: ' . microtime(true));
+		}
 	}
 
 	/**