Boot molto lento su Debian Sid

Ven, 18/05/2018 - 11:56

#11

azioga

(Geek)

Offline

Iscritto: 26/02/2018

Messaggi: 55

casomai il numero di sessioni da cancellare è tale che il tempo impiegato è quello giusto.

potresti provare ad eseguire a mano /usr/lib/php/sessionclean, in modo da creare una situazione pulita e poi far ripartire la macchina.

Sab, 19/05/2018 - 13:55

#12

homeless

(Guru)

Offline

Iscritto: 21/10/2011

Messaggi: 1453

Scusatemi se mi inserisco. Se il rallentamento è legato al servizio phpsessionclean.service, richiamando tale servizio lo script /usr/lib/php/sessionclean, e non potendo eliminare questo script, potrebbe essere utile analizzare perché è così lento in fase di avvio del sistema operativo; a tal fine, potresti effettuare un profiling del file, per cercare eventuali colli di bottiglia nella condizione in cui è lento; potresti farlo, ad esempio, con il comando:

script log.txt
/usr/bin/time -v $(PS4='$(date "+%s.%N ($LINENO) + ")' bash -x /usr/lib/php/sessionclean)
exit

Nel file log.txt saranno disponibili per ciascuna riga dello script i tempi in secondi e nanosecondi di esecuzione della riga, in modo da poter eventualmente elaborare delle tempistiche di esecuzione ed identificare eventuali colli di bottiglia.

Una curiosità: su che hardware (computer, disco) è in esecuzione il server ?

In ogni caso, considera che il pacchetto sorgente php-defaults da cui dipende anche php-common è stato aggiornato il Debian Sid lo scorso 12 aprile 2018 e questo potrebbe spiegare perché il malfunzionamento si presenta da pochi giorni: quale versione è attualmente installata ? Hai eseguito aggiornamenti recenti ?

Dom, 20/05/2018 - 11:24

#13

gmat

(Geek)

Offline

Iscritto: 14/11/2013

Messaggi: 63

Ciao. Grazie mille del suggerimento.

Gira tutto su un Dell latitude con disco ssd, quindi non credo che ci siamo problemi derivanti da questo.

Eseguo aggiornamenti più o meno ogni settimana, ma solo dopo aver analizzato eventuali gravi bug e non mi sembra proprio che php-defaults fosse affetto da un bug grave.

Grazie per i suggerimenti

Ecco l'output del file:

Script started on 2018-05-20 11:22:07+02:00
/usr/bin/time -v $(PS4='$(date "+%s.%N ($LINENO) + ")' bash -x /usr/lib/php/sessionclean)
exit]0;matteo@debian: ~[01;32mmatteo@debian[00m:[01;34m~[00m$ /usr/bin/time -v $(PS4='$(date "+%s.%N ($LINENO) + ")' bash -x /usr/lib/php/sessionclean)
1526808127.073867598 (24) + SAPIS='apache2:apache2 apache2filter:apache2 cgi:php@VERSION@ fpm:php-fpm@VERSION@ cli:php@VERSION@'
1526808127.075374115 (28) + proc_names=
1526808127.075532097 (52) + sort -u -t: -k 1,1
1526808127.075572223 (51) + sort -rn -t: -k2,2
1526808127.075673705 (53) + IFS=:
1526808127.076759836 (53) + read -r save_path gc_maxlifetime
11526808127.077066284 (29) + /usr/sbin/phpquery -V
1526808127.092191887 (29) + for version in $(/usr/sbin/phpquery -V)
1526808127.095224562 (30) + for sapi in ${SAPIS}
1526808127.097548241 (31) + conf_dir=apache2
1526808127.100182613 (32) + proc_name=apache2
1526808127.101647182 (33) + '[' -e /etc/php/7.2/apache2/php.ini ']'
11526808127.102973947 (35) + PHP_INI_SCAN_DIR=/etc/php/7.2/apache2/conf.d/
11526808127.104026550 (35) + php7.2 -c /etc/php/7.2/apache2/php.ini -d 'error_reporting='\''~E_ALL'\''' -r 'foreach(ini_get_all("session") as $k => $v) echo "$k=".$v["local_value"]."\n";'
1526808127.204548301 (35) + session_config='session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
11526808127.206193613 (36) + sed -ne 's/^session\.save_handler=\(.*\)$/\1/p'
11526808127.206193610 (36) + echo 'session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
1526808127.208550777 (36) + save_handler=files
11526808127.210071502 (37) + echo 'session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
11526808127.210071491 (37) + sed -ne 's/^session\.save_path=\(.*;\)\?\(.*\)$/\2/p'
1526808127.212671561 (37) + save_path=/var/lib/php/sessions
11526808127.214185533 (38) + sed -ne 's/^session\.gc_maxlifetime=\(.*\)$/\1/p'
11526808127.214185529 (38) + echo 'session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
1526808127.216523458 (38) + gc_maxlifetime=24
1526808127.217644986 (40) + '[' files = files -a -d /var/lib/php/sessions ']'
11526808127.219406099 (41) + echo apache2
11526808127.219450719 (41) + sed -e s,@VERSION@,7.2,
1526808127.221934966 (41) + proc_names=' apache2'
1526808127.222841754 (42) + printf '%s:%s\n' /var/lib/php/sessions 24
1526808127.223766790 (30) + for sapi in ${SAPIS}
1526808127.224699228 (31) + conf_dir=apache2filter
1526808127.225574435 (32) + proc_name=apache2
1526808127.226431025 (33) + '[' -e /etc/php/7.2/apache2filter/php.ini ']'
1526808127.227319622 (30) + for sapi in ${SAPIS}
1526808127.228216690 (31) + conf_dir=cgi
1526808127.229085124 (32) + proc_name=php@VERSION@
1526808127.229949344 (33) + '[' -e /etc/php/7.2/cgi/php.ini ']'
1526808127.230781280 (30) + for sapi in ${SAPIS}
1526808127.231817958 (31) + conf_dir=fpm
1526808127.232916255 (32) + proc_name=php-fpm@VERSION@
1526808127.239455940 (33) + '[' -e /etc/php/7.2/fpm/php.ini ']'
1526808127.246134880 (30) + for sapi in ${SAPIS}
1526808127.250001378 (31) + conf_dir=cli
1526808127.253847014 (32) + proc_name=php@VERSION@
1526808127.257173957 (33) + '[' -e /etc/php/7.2/cli/php.ini ']'
11526808127.258680600 (35) + PHP_INI_SCAN_DIR=/etc/php/7.2/cli/conf.d/
11526808127.260473487 (35) + php7.2 -c /etc/php/7.2/cli/php.ini -d 'error_reporting='\''~E_ALL'\''' -r 'foreach(ini_get_all("session") as $k => $v) echo "$k=".$v["local_value"]."\n";'
1526808127.313420839 (35) + session_config='session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
11526808127.319549073 (36) + sed -ne 's/^session\.save_handler=\(.*\)$/\1/p'
11526808127.319382529 (36) + echo 'session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
1526808127.329123228 (36) + save_handler=files
11526808127.331283999 (37) + sed -ne 's/^session\.save_path=\(.*;\)\?\(.*\)$/\2/p'
11526808127.331271600 (37) + echo 'session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
1526808127.333891344 (37) + save_path=/var/lib/php/sessions
11526808127.335448481 (38) + echo 'session.auto_start=0
session.cache_expire=180
session.cache_limiter=nocache
session.cookie_domain=
session.cookie_httponly=
session.cookie_lifetime=0
session.cookie_path=/
session.cookie_secure=0
session.gc_divisor=1000
session.gc_maxlifetime=1440
session.gc_probability=0
session.lazy_write=1
session.name=PHPSESSID
session.referer_check=
session.save_handler=files
session.save_path=/var/lib/php/sessions
session.serialize_handler=php
session.sid_bits_per_character=5
session.sid_length=26
session.upload_progress.cleanup=1
session.upload_progress.enabled=1
session.upload_progress.freq=1%
session.upload_progress.min_freq=1
session.upload_progress.name=PHP_SESSION_UPLOAD_PROGRESS
session.upload_progress.prefix=upload_progress_
session.use_cookies=1
session.use_only_cookies=1
session.use_strict_mode=0
session.use_trans_sid=0'
11526808127.335495541 (38) + sed -ne 's/^session\.gc_maxlifetime=\(.*\)$/\1/p'
1526808127.338078335 (38) + gc_maxlifetime=24
1526808127.339050238 (40) + '[' files = files -a -d /var/lib/php/sessions ']'
11526808127.340749552 (41) + echo php@VERSION@
11526808127.340988551 (41) + sed -e s,@VERSION@,7.2,
1526808127.343678116 (41) + proc_names=' apache2 php7.2'
1526808127.344664092 (42) + printf '%s:%s\n' /var/lib/php/sessions 24
11526808127.345985846 (48) + pidof apache2 php7.2
1526808127.358415212 (48) + for pid in $(pidof $proc_names)
1526808127.361570226 (49) + find /proc/2735/fd -ignore_readdir_race -lname '/var/lib/php/sessions/sess_*' -exec touch -c '{}' ';'
1526808127.368044484 (48) + for pid in $(pidof $proc_names)
1526808127.370751927 (49) + find /proc/2734/fd -ignore_readdir_race -lname '/var/lib/php/sessions/sess_*' -exec touch -c '{}' ';'
1526808127.374967173 (48) + for pid in $(pidof $proc_names)
1526808127.375812528 (49) + find /proc/2733/fd -ignore_readdir_race -lname '/var/lib/php/sessions/sess_*' -exec touch -c '{}' ';'
1526808127.377622526 (48) + for pid in $(pidof $proc_names)
1526808127.378458355 (49) + find /proc/2731/fd -ignore_readdir_race -lname '/var/lib/php/sessions/sess_*' -exec touch -c '{}' ';'
1526808127.380333365 (48) + for pid in $(pidof $proc_names)
1526808127.381149949 (49) + find /proc/2728/fd -ignore_readdir_race -lname '/var/lib/php/sessions/sess_*' -exec touch -c '{}' ';'
1526808127.382950637 (48) + for pid in $(pidof $proc_names)
1526808127.383743142 (49) + find /proc/2146/fd -ignore_readdir_race -lname '/var/lib/php/sessions/sess_*' -exec touch -c '{}' ';'
1526808127.385679459 (48) + for pid in $(pidof $proc_names)
1526808127.386475300 (49) + find /proc/2145/fd -ignore_readdir_rac

Dom, 20/05/2018 - 17:08

#14

homeless

(Guru)

Offline

Iscritto: 21/10/2011

Messaggi: 1453

Il log che hai inviato è troncato; dovresti inviarlo come file allegato (magari compresso). Con l'occasione, modifica lo script in questo modo:

script log.txt
PS4='$(date "+%s.%N ($LINENO) + ")' /usr/bin/time -v  bash -x ./usr/lib/php/sessionclean
exit

Dom, 20/05/2018 - 22:41

#15

mcortese

(Moderatore)

Offline

Iscritto: 27/02/2009

Messaggi: 2918

Una definizione ancora migliore di PS4 è qualcosa tipo:

PS4='+ $(date +%s.%N) ($LINENO) '

Infatti, il primo carattere di PS4 viene ripetuto più volte per indicare il livello di ridirezione. Se è un carattere facile da individuare come + si vede a colpo d'occhio. La definizione precedente, invece, inizia subito con un numero (secondi), quindi il primo carattere è la prima cifra di quel numero (1): quando viene raddoppiato, dà origine a un altro numero e non è immediato capire perché dopo la riga 53 si passa dal secondo "1 miliardo e rotti" al secondo "11 miliardi e rotti".

Ven, 22/06/2018 - 12:08

#16

gmat

(Geek)

Offline

Iscritto: 14/11/2013

Messaggi: 63

Ciao ragazzi,

vi chiedo scusa per l'enorme ritardo della risposta, ma per diverso tempo il forum non si apriva e sono stato in giro per lavoro diverso tempo e con poca aria da respirare.

Mi sono accorto di una cosa piuttosto singolare. Il problema c'è ancora, MA, non appena inserisco la password e INIZIO a muovere il mouse (o touchpad che sia) il boot viene subito eseguito. Se non tocco niente ci vogliono sempre diversi minuti.

Vi ringrazio ancora e mi scuso ancora per il ritardo

Sab, 23/06/2018 - 02:11

#17

mcortese

(Moderatore)

Offline

Iscritto: 27/02/2009

Messaggi: 2918

Allora sei vittima di questa modifica del kernel apparsa a un certo punto tra la versione 4.16 e 4.17.

La modifica interessa la generazione di numeri casuali. Il kernel ha un serbatoio di entropia da cui tira fuori i numeri casuali ogni volta che qualche processo ne fa richiesta tramite la funzione getrandom(). Questo serbatoio è alimentato mischiando dati tra loro non correlati e non prevedibili, come il tempo in millisecondi tra un interrupt e l'altro, o tra la pressione dei tasti o i movimenti del mouse, ecc.

All'avvio il serbatoio è vuoto perché il kernel non ha ancora raccolto abbastanza di questi dati. Se una richiesta di un numero casuale arriva in questo momento, il kernel può fare due cose: far attendere il processo fino a quando non è disponibile una quantità di entropia minima perché il numero possa dirsi davvero imprevedibile, oppure calcolare subito un numero pseudocasuale sulla base della poca entropia che ha, ben sapendo che tale numero può essere facilmente indovinato da un osservatore esterno. La funzione getrandom() accetta un parametro (GRND_NONBLOCK) che dice al kernel: «Ho bisogno di un numero casuale sicuro, se ce l'hai, ma non farmi aspettare se non ce l'hai, mi va bene anche qualcosa di meno sicuro». Se manca questo flag, invece, la richiesta è di avere un numero crittograficamente sicuro, anche a costo di dover aspettare che il serbatoio di entropia si riempia.

Prima della modifica, il kernel erroneamente non controllava se il serbatoio era pieno o no e quindi restituiva sempre un numero, anche ai processi che ne volevano uno crittograficamente sicuro, generando così una falla di sicurezza (vedi CVE-2018-1108). A sua volta, questa leggerezza da parte del kernel ha fatto sì che i programmi terzi ne approfittassero: perché preoccuparsi di specificare il parametro GRND_NONBLOCK se tanto anche senza il comportamento è lo stesso?

Quando Ted Ts'o ha corretto il baco del kernel con la modifica menzionata sopra, i programmi che si erano adagiati sull'abitudine di chiamare getrandom() senza il flag anche quando non volevano aspettare, improvvisamente si sono visti bloccare dal kernel per un tempo indefinito in attesa di entropia. Il primo di tali programmi ad essere scoperto è stato Plymouth, grazie al baco #897572 (leggendo tutta la discussione si riesce a ricostruire la storia che ho sintetizzato qui).

Ovviamente la soluzione è correggere tutti quei programmi che usavano getrandom() nel modo sbagliato: un errore trascurabile prima della modifica, imperdonabile dopo. Plymouth è stato corretto, così come GDM e, immagino, molti altri programmi. Verifica se i pacchetti del tuo ambiente desktop sono effettivamente aggiornati all'ultima versione.

Se non puoi risolvere aggiornando, considera l'idea di segnalare un baco al manutentore del pacchetto incriminato, se non ce n'è già uno aperto. Nel frattempo, come soluzione tampone, nota che di solito basta muovere il mouse per qualche secondo per generare entropia sufficiente per completare l'avvio e il login. Se proprio ti è intollerabile, allora puoi sempre compilare il kernel dai sorgenti dopo aver "invertito" la modifica.

Sab, 23/06/2018 - 11:27

#18

gmat

(Geek)

Offline

Iscritto: 14/11/2013

Messaggi: 63

spiegazione impeccabile, ora è tutto chiaro.

Direi che per il momento mi accontento tranquillamente di muovere il mouse per generare un po' di entropia, sicuramente informerò i ragazzi di Cinnamon di questo problema (sempre che qualcuno non lo abbia già fatto).

Ti ringrazio, anzi Vi ringrazio tutti per la pazienza e disponibilità

Sab, 04/08/2018 - 01:26

#19

eternauta

(Junior)

Offline

Iscritto: 04/08/2018

Messaggi: 17

gmat ha scritto:
spiegazione impeccabile, ora è tutto chiaro.

Direi che per il momento mi accontento tranquillamente di muovere il mouse per generare un po' di entropia, sicuramente informerò i ragazzi di Cinnamon di questo problema (sempre che qualcuno non lo abbia già fatto).

Ti ringrazio, anzi Vi ringrazio tutti per la pazienza e disponibilità

Ringrazio mcortese per la spiegazione che definirei... cristallina!

Penso di essermi imbattuto nello stesso problema dopo l'aggiornamento del kernel di Buster dal 4.16 ecc. al 4.17.0-1. Se il problema è lo stesso, come credo, non è comunque un problema di Cinnamon in quanto a me si è verificato con Debian Buster con Mate e Gnome. Se a qualcuno può interessare, a me si è risolto tutto installando il pacchetto "haveged". Il suggerimento l'ho trovato qui: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=903945#15
Buona serata!

A questo mondo niente rimane uguale, la notte più lunga eterna non è. (Bertolt Brecht)
... sperem

Dom, 26/08/2018 - 10:45

#20

mcortese

(Moderatore)

Offline

Iscritto: 27/02/2009

Messaggi: 2918

Per i pochi che si compilano il kernel da sé, segnalo anche questa patch proposta da Ted Ts'o, ma non (ancora) accolta ufficialmente. Questo articolo di LWN ha dettagli in più. In pratica usa il generatore casuale insito nelle CPU più moderne, pratica che normalmente il kernel evita per via della scarsa fiducia (che rasenta la paranoia) nelle soluzioni puramente hardware non verificabili.

Boot molto lento su Debian Sid

Home

About

Network ILDN

Social link